2015-09-26 08:51:39.201 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager.update_available_resource from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:51:39.239 INFO nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Auditing locally available compute resources for node devstack2 2015-09-26 08:51:39.282 DEBUG nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Hypervisor: free VCPUs: 1 from (pid=2811) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:570 2015-09-26 08:51:39.282 DEBUG nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Hypervisor: assignable PCI devices: [{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=2811) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:578 2015-09-26 08:51:39.283 DEBUG nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Hypervisor/Node resource view: name=devstack2 free_ram=7583MB free_disk=2GB free_vcpus=1 pci_devices=[{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=2811) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:592 2015-09-26 08:51:39.284 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Lock "compute_resources" acquired by "nova.compute.resource_tracker._update_available_resource" :: waited 0.000s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 08:51:39.391 INFO nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Total usable vcpus: 1, total allocated vcpus: 0 2015-09-26 08:51:39.391 INFO nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Final resource view: name=devstack2 phys_ram=7984MB used_ram=512MB phys_disk=4GB used_disk=0GB total_vcpus=1 used_vcpus=0 pci_stats=None 2015-09-26 08:51:39.482 INFO nova.compute.resource_tracker [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Compute_service record updated for devstack2:devstack2 2015-09-26 08:51:39.483 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" :: held 0.199s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 08:51:55.426 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:51:55.426 DEBUG nova.compute.manager [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] CONF.reclaim_instance_interval <= 0, skipping... from (pid=2811) _reclaim_queued_deletes /home/stack/src/cloud/nova/nova/compute/manager.py:6084 2015-09-26 08:51:56.138 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager._check_instance_build_time from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:52:00.259 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `vcpu_model' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:00.281 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Instance launched has CPU info: {"vendor": "Intel", "model": "Nehalem", "arch": "x86_64", "features": ["pge", "avx", "clflush", "sep", "syscall", "tsc-deadline", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "cmov", "smep", "pcid", "pat", "lm", "msr", "nx", "fxsr", "sse4.1", "pae", "sse4.2", "pclmuldq", "fma", "vme", "mmx", "osxsave", "cx8", "mce", "de", "mca", "pse", "lahf_lm", "abm", "popcnt", "pdpe1gb", "apic", "sse", "f16c", "pni", "rdtscp", "avx2", "sse2", "ss", "hypervisor", "bmi1", "bmi2", "ssse3", "fpu", "cx16", "pse36", "mtrr", "movbe", "rdrand", "x2apic"], "topology": {"cores": 1, "threads": 1, "sockets": 1}} 2015-09-26 08:52:00.284 DEBUG nova.virt.libvirt.config [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Generated XML ('\n x86_64\n Nehalem\n Intel\n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n\n',)  from (pid=2811) to_xml /home/stack/src/cloud/nova/nova/virt/libvirt/config.py:82 2015-09-26 08:52:00.287 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Creating tmpfile /home/stack/src/cloud/data/nova/instances/tmpQkTrUY to notify to other compute nodes that they should mount the same storage. from (pid=2811) _create_shared_storage_test_file /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:5331 2015-09-26 08:52:01.538 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:01.538 DEBUG nova.network.neutronv2.api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _get_instance_nw_info() from (pid=2811) _get_instance_nw_info /home/stack/src/cloud/nova/nova/network/neutronv2/api.py:922 2015-09-26 08:52:01.555 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:01.556 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:01.557 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:01.794 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-26c7d4df-d50c-4a83-89f6-66f1615bb09f RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:01.796 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/networks.json?id=c16b9c17-a4c6-41ec-adcc-2800accbb727 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:01.832 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 454 x-openstack-request-id: req-271f2f1d-f555-4aac-a66a-def1649120ce RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["288075d8-b675-44d1-a50b-8832986c7d96", "ef534dcc-7e40-461c-865f-b64199d5a8a0"], "name": "private", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mtu": 0, "router:external": false, "shared": false, "port_security_enabled": true, "provider:network_type": "vxlan", "id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "provider:segmentation_id": 1041}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:01.834 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=10.1.0.3&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:01.845 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-f8295dda-d9cb-4c11-85ee-eb0de1799b54 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:01.846 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=fdbd%3A4e3b%3Ace09%3A0%3Af816%3A3eff%3Afe83%3A44aa&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:01.862 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-a055172a-966c-46f9-be19-2321107e1ee8 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:01.863 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/subnets.json?id=288075d8-b675-44d1-a50b-8832986c7d96&id=ef534dcc-7e40-461c-865f-b64199d5a8a0 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:01.953 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 964 x-openstack-request-id: req-88e8f6c8-19d7-4f85-ad5b-3362d8aff9af RESP BODY: {"subnets": [{"name": "private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "10.1.0.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "10.1.0.2", "end": "10.1.0.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "10.1.0.0/24", "id": "288075d8-b675-44d1-a50b-8832986c7d96", "subnetpool_id": null}, {"name": "ipv6-private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "fdbd:4e3b:ce09::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "fdbd:4e3b:ce09::2", "end": "fdbd:4e3b:ce09:0:ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "fdbd:4e3b:ce09::/64", "id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "subnetpool_id": null}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:01.955 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:02.090 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-9a34cb25-1538-407d-8ec1-3365bb699443 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:02.092 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:02.179 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:01 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-a1e4a535-4880-48ae-9158-258425267268 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:02.181 DEBUG nova.network.base_api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Updating instance_info_cache with network_info: [VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.1.0.3'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'meta': {}, 'version': 6, 'type': 'fixed', 'floating_ips': [], 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None})] from (pid=2811) update_instance_cache_with_nw_info /home/stack/src/cloud/nova/nova/network/base_api.py:43 2015-09-26 08:52:02.201 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:02.201 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `flavor' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:02.282 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] migrate_data in pre_live_migration: {u'disk_over_commit': False, u'disk_available_mb': 2048, u'image_type': u'default', u'is_shared_instance_path': False, u'filename': u'tmpQkTrUY', u'instance_relative_path': u'3d6a16d5-6678-474e-9710-682473d1d98c', u'block_migration': True, u'is_shared_block_storage': False, u'is_volume_backed': False, u'is_shared_storage': False} from (pid=2811) pre_live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6140 2015-09-26 08:52:02.283 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Creating instance directory: /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) pre_live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6173 2015-09-26 08:52:02.283 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking to make sure images and backing files are present before live migration. from (pid=2811) pre_live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6179 2015-09-26 08:52:02.284 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "/home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 08:52:02.285 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "/home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 08:52:02.286 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:02.379 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea" returned: 0 in 0.093s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:02.381 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "7eb0bb2db79ba82008d71f9d6a295006c45db4ea" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 08:52:02.381 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:02.471 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea" returned: 0 in 0.090s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:02.473 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:02.650 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "qemu-img create -f qcow2 -o backing_file=/home/stack/src/cloud/data/nova/instances/_base/7eb0bb2db79ba82008d71f9d6a295006c45db4ea /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.177s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:02.651 DEBUG nova.virt.disk.api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Checking if we can resize image /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk. size=1073741824 from (pid=2811) can_resize_image /home/stack/src/cloud/nova/nova/virt/disk/api.py:229 2015-09-26 08:52:02.652 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:02.747 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.095s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:02.748 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): qemu-img resize /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk 1073741824 from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:02.949 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "qemu-img resize /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk 1073741824" returned: 0 in 0.201s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:02.951 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "7eb0bb2db79ba82008d71f9d6a295006c45db4ea" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.570s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 08:52:02.952 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Plugging VIFs before live migration. from (pid=2811) pre_live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6229 2015-09-26 08:52:02.953 DEBUG nova.virt.libvirt.vif [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='',created_at=2015-09-21T14:30:15Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='vm1',display_name='vm1',ec2_ids=,ephemeral_gb=0,ephemeral_key_uuid=None,fault=,flavor=Flavor(2),host='devstack1',hostname='vm1',id=1,image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCf2XROOJlSLcFyoGJYecfQGaVa8hSyrnvq4SyVkZ78IpLsgKDp1BoZl3pIHpjaHNPrxbsOaAGno2V/Ux+4JGku9cBrmHtDJ5CzPTE74uffqxayGeM0MYmcJ+Z5cGlQFUxLzYmhSnZtrT9jG+V2lu7HI+ORX6YKQaFlPCWWdTTt0Bty8jgVvAyc9L+isGYcouMWj8/CTWpY0UmIflNhuVeQl7LCG06DdohQtnEjUWrasgY8G8Cz0zIke6OWAzYREN+6L+M++D+9SvPFANdDJ0xV3RXp1FJ9iwNg6YUJrnq5f+nJol3GjwgegbMz6/eaOeiPpm5q0Ldg/wTez3SyBaPX Generated-by-Nova',key_name='oskey1',launch_index=0,launched_at=2015-09-21T14:30:26Z,launched_on='devstack1',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=,new_flavor=None,node='devstack1',numa_topology=,old_flavor=None,os_type=None,pci_devices=,pci_requests=,power_state=1,progress=0,project_id='c392e44c09ce4cc9b3e77e79df76a81f',ramdisk_id='',reservation_id='r-oi2xpo6i',root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='2',image_base_image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0'},tags=,task_state='migrating',terminated_at=None,updated_at=2015-09-26T12:47:29Z,user_data=None,user_id='0457270a4f9a461b8b3d6599ce31f96b',uuid=3d6a16d5-6678-474e-9710-682473d1d98c,vcpu_model=,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.1.0.3', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'version': 6, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa', 'type': 'fixed'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None}) from (pid=2811) plug /home/stack/src/cloud/nova/nova/virt/libvirt/vif.py:717 2015-09-26 08:52:02.958 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbrda4ab1e3-be from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.069 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbrda4ab1e3-be" returned: 0 in 0.111s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.070 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbrda4ab1e3-be 0 from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.154 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbrda4ab1e3-be 0" returned: 0 in 0.084s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.156 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbrda4ab1e3-be off from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.235 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbrda4ab1e3-be off" returned: 0 in 0.079s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.236 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbrda4ab1e3-be/bridge/multicast_snooping from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.314 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbrda4ab1e3-be/bridge/multicast_snooping" returned: 0 in 0.078s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.315 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvbda4ab1e3-be type veth peer name qvoda4ab1e3-be from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.416 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvbda4ab1e3-be type veth peer name qvoda4ab1e3-be" returned: 0 in 0.101s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.417 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvbda4ab1e3-be up from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.539 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvbda4ab1e3-be up" returned: 0 in 0.122s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.540 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvbda4ab1e3-be promisc on from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.637 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvbda4ab1e3-be promisc on" returned: 0 in 0.097s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.639 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvoda4ab1e3-be up from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.722 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvoda4ab1e3-be up" returned: 0 in 0.083s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.723 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvoda4ab1e3-be promisc on from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.802 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvoda4ab1e3-be promisc on" returned: 0 in 0.079s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.804 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbrda4ab1e3-be up from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.887 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbrda4ab1e3-be up" returned: 0 in 0.083s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:03.889 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbrda4ab1e3-be qvbda4ab1e3-be from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:03.988 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbrda4ab1e3-be qvbda4ab1e3-be" returned: 0 in 0.099s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:04.000 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvoda4ab1e3-be -- add-port br-int qvoda4ab1e3-be -- set Interface qvoda4ab1e3-be external-ids:iface-id=da4ab1e3-be0d-4c24-8a90-d863aa189577 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:83:44:aa external-ids:vm-uuid=3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 08:52:04.161 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvoda4ab1e3-be -- add-port br-int qvoda4ab1e3-be -- set Interface qvoda4ab1e3-be external-ids:iface-id=da4ab1e3-be0d-4c24-8a90-d863aa189577 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:83:44:aa external-ids:vm-uuid=3d6a16d5-6678-474e-9710-682473d1d98c" returned: 0 in 0.160s from (pid=2811) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 08:52:05.848 DEBUG nova.virt.driver [-] Emitting event Started> from (pid=2811) emit_event /home/stack/src/cloud/nova/nova/virt/driver.py:1303 2015-09-26 08:52:05.848 INFO nova.compute.manager [-] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] VM Started (Lifecycle Event) 2015-09-26 08:52:06.133 DEBUG nova.compute.manager [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking state from (pid=2811) _get_power_state /home/stack/src/cloud/nova/nova/compute/manager.py:1328 2015-09-26 08:52:08.147 DEBUG nova.virt.driver [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] Emitting event Resumed> from (pid=2811) emit_event /home/stack/src/cloud/nova/nova/virt/driver.py:1303 2015-09-26 08:52:08.148 INFO nova.compute.manager [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] VM Resumed (Lifecycle Event) 2015-09-26 08:52:08.450 DEBUG nova.compute.manager [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking state from (pid=2811) _get_power_state /home/stack/src/cloud/nova/nova/compute/manager.py:1328 2015-09-26 08:52:08.456 DEBUG nova.compute.manager [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Synchronizing instance power state after lifecycle event "Resumed"; current vm_state: active, current task_state: migrating, current DB power_state: 1, VM power_state: 1 from (pid=2811) handle_lifecycle_event /home/stack/src/cloud/nova/nova/compute/manager.py:1257 2015-09-26 08:52:08.614 INFO nova.compute.manager [req-3d02fa4d-4d8f-4fbf-87bf-93a241b0506e None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] During the sync_power process the instance has moved from host devstack1 to host devstack2 2015-09-26 08:52:10.794 INFO nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Post operation of migration started 2015-09-26 08:52:10.795 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/extensions.json -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:10.805 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:10 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 4074 x-openstack-request-id: req-f2b37527-daec-4545-9f0f-9876d631b6ed RESP BODY: {"extensions": [{"alias": "dns-integration", "updated": "2015-08-15T18:00:00-00:00", "name": "DNS Integration", "links": [], "description": "Provides integration with internal DNS."}, {"alias": "ext-gw-mode", "updated": "2013-03-28T10:00:00-00:00", "name": "Neutron L3 Configurable external gateway mode", "links": [], "description": "Extension of the router abstraction for specifying whether SNAT should occur on the external gateway"}, {"alias": "binding", "updated": "2014-02-03T10:00:00-00:00", "name": "Port Binding", "links": [], "description": "Expose port bindings of a virtual port to external application"}, {"alias": "agent", "updated": "2013-02-03T10:00:00-00:00", "name": "agent", "links": [], "description": "The agent management extension."}, {"alias": "subnet_allocation", "updated": "2015-03-30T10:00:00-00:00", "name": "Subnet Allocation", "links": [], "description": "Enables allocation of subnets from a subnet pool"}, {"alias": "l3_agent_scheduler", "updated": "2013-02-07T10:00:00-00:00", "name": "L3 Agent Scheduler", "links": [], "description": "Schedule routers among l3 agents"}, {"alias": "external-net", "updated": "2013-01-14T10:00:00-00:00", "name": "Neutron external network", "links": [], "description": "Adds external network attribute to network resource."}, {"alias": "flavors", "updated": "2014-07-06T10:00:00-00:00", "name": "Neutron Service Flavors", "links": [], "description": "Service specification for advanced services"}, {"alias": "net-mtu", "updated": "2015-03-25T10:00:00-00:00", "name": "Network MTU", "links": [], "description": "Provides MTU attribute for a network resource."}, {"alias": "quotas", "updated": "2012-07-29T10:00:00-00:00", "name": "Quota management support", "links": [], "description": "Expose functions for quotas management per tenant"}, {"alias": "l3-ha", "updated": "2014-04-26T00:00:00-00:00", "name": "HA Router extension", "links": [], "description": "Add HA capability to routers."}, {"alias": "provider", "updated": "2012-09-07T10:00:00-00:00", "name": "Provider Network", "links": [], "description": "Expose mapping of virtual networks to physical networks"}, {"alias": "multi-provider", "updated": "2013-06-27T10:00:00-00:00", "name": "Multi Provider Network", "links": [], "description": "Expose mapping of virtual networks to multiple physical networks"}, {"alias": "extraroute", "updated": "2013-02-01T10:00:00-00:00", "name": "Neutron Extra Route", "links": [], "description": "Extra routes configuration for L3 router"}, {"alias": "router", "updated": "2012-07-20T10:00:00-00:00", "name": "Neutron L3 Router", "links": [], "description": "Router abstraction for basic L3 forwarding between L2 Neutron networks and access to external networks via a NAT gateway."}, {"alias": "extra_dhcp_opt", "updated": "2013-03-17T12:00:00-00:00", "name": "Neutron Extra DHCP opts", "links": [], "description": "Extra options configuration for DHCP. For example PXE boot options to DHCP clients can be specified (e.g. tftp-server, server-ip-address, bootfile-name)"}, {"alias": "security-group", "updated": "2012-10-05T10:00:00-00:00", "name": "security-group", "links": [], "description": "The security groups extension."}, {"alias": "dhcp_agent_scheduler", "updated": "2013-02-07T10:00:00-00:00", "name": "DHCP Agent Scheduler", "links": [], "description": "Schedule networks among dhcp agents"}, {"alias": "rbac-policies", "updated": "2015-06-17T12:15:12-30:00", "name": "RBAC Policies", "links": [], "description": "Allows creation and modification of policies that control tenant access to resources."}, {"alias": "port-security", "updated": "2012-07-23T10:00:00-00:00", "name": "Port Security", "links": [], "description": "Provides port security"}, {"alias": "allowed-address-pairs", "updated": "2013-07-23T10:00:00-00:00", "name": "Allowed Address Pairs", "links": [], "description": "Provides allowed address pairs"}, {"alias": "dvr", "updated": "2014-06-1T10:00:00-00:00", "name": "Distributed Virtual Router", "links": [], "description": "Enables configuration of Distributed Virtual Routers."}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:10.807 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:10.808 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:10.809 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:10.996 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:10 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-244776b7-315a-4251-b3fe-315774d08d45 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:10.997 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X PUT http://192.169.143.120:9696/v2.0/ports/da4ab1e3-be0d-4c24-8a90-d863aa189577.json -H "User-Agent: python-neutronclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" -d '{"port": {"binding:host_id": "devstack2"}}' from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:11.958 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:11 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 885 x-openstack-request-id: req-2ce21579-28c0-4e5a-ad63-d094bad68211 RESP BODY: {"port": {"status": "ACTIVE", "binding:host_id": "devstack2", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:11.959 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:11.960 DEBUG nova.network.neutronv2.api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _get_instance_nw_info() from (pid=2811) _get_instance_nw_info /home/stack/src/cloud/nova/nova/network/neutronv2/api.py:922 2015-09-26 08:52:12.009 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:12.009 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:12.010 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.197 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:11 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-e93044ab-970a-438f-98c1-d7476eb022a8 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack2", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.198 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/networks.json?id=c16b9c17-a4c6-41ec-adcc-2800accbb727 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.265 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 454 x-openstack-request-id: req-4d4174ae-9847-44ab-a009-b706750ba205 RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["288075d8-b675-44d1-a50b-8832986c7d96", "ef534dcc-7e40-461c-865f-b64199d5a8a0"], "name": "private", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mtu": 0, "router:external": false, "shared": false, "port_security_enabled": true, "provider:network_type": "vxlan", "id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "provider:segmentation_id": 1041}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.267 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=10.1.0.3&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.286 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-0b016bb9-3aba-49f7-89e4-73fe8e2cc51d RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.287 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=fdbd%3A4e3b%3Ace09%3A0%3Af816%3A3eff%3Afe83%3A44aa&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.298 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-6a686eb8-448c-4117-ac7f-4d8a9ea8ca88 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.299 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/subnets.json?id=288075d8-b675-44d1-a50b-8832986c7d96&id=ef534dcc-7e40-461c-865f-b64199d5a8a0 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.346 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 964 x-openstack-request-id: req-b8f97bb6-200b-411b-8e91-5b3f7c88e571 RESP BODY: {"subnets": [{"name": "private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "10.1.0.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "10.1.0.2", "end": "10.1.0.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "10.1.0.0/24", "id": "288075d8-b675-44d1-a50b-8832986c7d96", "subnetpool_id": null}, {"name": "ipv6-private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "fdbd:4e3b:ce09::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "fdbd:4e3b:ce09::2", "end": "fdbd:4e3b:ce09:0:ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "fdbd:4e3b:ce09::/64", "id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "subnetpool_id": null}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.348 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.435 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-68fc567d-6b93-4d5f-8457-215734fae961 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.436 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:12.522 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:12 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-fc826a32-8771-49bd-9390-dc55fd8fb822 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:12.524 DEBUG nova.network.base_api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Updating instance_info_cache with network_info: [VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.1.0.3'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'meta': {}, 'version': 6, 'type': 'fixed', 'floating_ips': [], 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None})] from (pid=2811) update_instance_cache_with_nw_info /home/stack/src/cloud/nova/nova/network/base_api.py:43 2015-09-26 08:52:12.547 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:12.565 DEBUG nova.block_device [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] block_device_list [] from (pid=2811) volume_in_mapping /home/stack/src/cloud/nova/nova/block_device.py:584 2015-09-26 08:52:12.566 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Start _get_guest_xml network_info=[VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.1.0.3', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'version': 6, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa', 'type': 'fixed'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None})] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {'disk': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}, 'root': {'bus': 'virtio', 'boot_index': '1', 'type': 'disk', 'dev': u'vda'}}} image_meta=ImageMeta(checksum=,container_format='bare',created_at=,direct_url=,disk_format='qcow2',id=,min_disk=1,min_ram=0,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=) rescue=None block_device_info={'swap': None, 'root_device_name': u'/dev/vda', 'ephemerals': [], 'block_device_mapping': []} from (pid=2811) _get_guest_xml /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:4320 2015-09-26 08:52:12.567 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `pci_devices' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:12.672 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `numa_topology' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:12.705 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Getting desirable topologies for flavor Flavor(created_at=None,deleted=False,deleted_at=None,disabled=False,ephemeral_gb=0,extra_specs={},flavorid='1',id=2,is_public=True,memory_mb=512,name='m1.tiny',projects=,root_gb=1,rxtx_factor=1.0,swap=0,updated_at=None,vcpu_weight=0,vcpus=1) and image_meta ImageMeta(checksum=,container_format='bare',created_at=,direct_url=,disk_format='qcow2',id=,min_disk=1,min_ram=0,name=,owner=,properties=ImageMetaProps,protected=,size=,status=,tags=,updated_at=,virtual_size=,visibility=), allow threads: True from (pid=2811) _get_desirable_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:564 2015-09-26 08:52:12.706 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Flavor limits 65536:65536:65536 from (pid=2811) _get_cpu_topology_constraints /home/stack/src/cloud/nova/nova/virt/hardware.py:308 2015-09-26 08:52:12.707 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Image limits 65536:65536:65536 from (pid=2811) _get_cpu_topology_constraints /home/stack/src/cloud/nova/nova/virt/hardware.py:319 2015-09-26 08:52:12.708 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Flavor pref -1:-1:-1 from (pid=2811) _get_cpu_topology_constraints /home/stack/src/cloud/nova/nova/virt/hardware.py:342 2015-09-26 08:52:12.708 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Image pref -1:-1:-1 from (pid=2811) _get_cpu_topology_constraints /home/stack/src/cloud/nova/nova/virt/hardware.py:361 2015-09-26 08:52:12.709 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Chosen -1:-1:-1 limits 65536:65536:65536 from (pid=2811) _get_cpu_topology_constraints /home/stack/src/cloud/nova/nova/virt/hardware.py:390 2015-09-26 08:52:12.709 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Topology preferred VirtCPUTopology(cores=-1,sockets=-1,threads=-1), maximum VirtCPUTopology(cores=65536,sockets=65536,threads=65536) from (pid=2811) _get_desirable_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:568 2015-09-26 08:52:12.710 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Build topologies for 1 vcpu(s) 1:1:1 from (pid=2811) _get_possible_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:429 2015-09-26 08:52:12.710 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Got 1 possible topologies from (pid=2811) _get_possible_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:456 2015-09-26 08:52:12.711 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Possible topologies [VirtCPUTopology(cores=1,sockets=1,threads=1)] from (pid=2811) _get_desirable_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:573 2015-09-26 08:52:12.711 DEBUG nova.virt.hardware [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Sorted desired topologies [VirtCPUTopology(cores=1,sockets=1,threads=1)] from (pid=2811) _get_desirable_cpu_topologies /home/stack/src/cloud/nova/nova/virt/hardware.py:598 2015-09-26 08:52:12.712 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `vcpu_model' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:12.733 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Path '/home/stack/src/cloud/data/nova/instances' supports direct I/O from (pid=2811) _supports_direct_io /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:2619 2015-09-26 08:52:12.736 DEBUG nova.virt.libvirt.vif [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='',created_at=2015-09-21T14:30:15Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='vm1',display_name='vm1',ec2_ids=,ephemeral_gb=0,ephemeral_key_uuid=None,fault=,flavor=Flavor(2),host='devstack1',hostname='vm1',id=1,image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCf2XROOJlSLcFyoGJYecfQGaVa8hSyrnvq4SyVkZ78IpLsgKDp1BoZl3pIHpjaHNPrxbsOaAGno2V/Ux+4JGku9cBrmHtDJ5CzPTE74uffqxayGeM0MYmcJ+Z5cGlQFUxLzYmhSnZtrT9jG+V2lu7HI+ORX6YKQaFlPCWWdTTt0Bty8jgVvAyc9L+isGYcouMWj8/CTWpY0UmIflNhuVeQl7LCG06DdohQtnEjUWrasgY8G8Cz0zIke6OWAzYREN+6L+M++D+9SvPFANdDJ0xV3RXp1FJ9iwNg6YUJrnq5f+nJol3GjwgegbMz6/eaOeiPpm5q0Ldg/wTez3SyBaPX Generated-by-Nova',key_name='oskey1',launch_index=0,launched_at=2015-09-21T14:30:26Z,launched_on='devstack1',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=,new_flavor=None,node='devstack1',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=,power_state=1,progress=0,project_id='c392e44c09ce4cc9b3e77e79df76a81f',ramdisk_id='',reservation_id='r-oi2xpo6i',root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='2',image_base_image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0'},tags=,task_state='migrating',terminated_at=None,updated_at=2015-09-26T12:51:59Z,user_data=None,user_id='0457270a4f9a461b8b3d6599ce31f96b',uuid=3d6a16d5-6678-474e-9710-682473d1d98c,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.1.0.3', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'version': 6, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa', 'type': 'fixed'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None}) virt_typekvm from (pid=2811) get_config /home/stack/src/cloud/nova/nova/virt/libvirt/vif.py:448 2015-09-26 08:52:12.740 DEBUG nova.virt.libvirt.config [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Generated XML ('\n 3d6a16d5-6678-474e-9710-682473d1d98c\n instance-00000001\n 524288\n 1\n \n \n \n vm1\n 2015-09-26 12:52:12\n \n 512\n 1\n 0\n 0\n 1\n \n \n admin\n demo\n \n \n \n \n \n \n OpenStack Foundation\n OpenStack Nova\n 12.0.0\n 464493d4-7872-43c0-b9c2-5f5085d5dc5b\n 3d6a16d5-6678-474e-9710-682473d1d98c\n Virtual Machine\n \n \n \n hvm\n \n \n \n \n \n \n \n \n 1024\n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n \n\n',)  from (pid=2811) to_xml /home/stack/src/cloud/nova/nova/virt/libvirt/config.py:82 2015-09-26 08:52:12.741 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] End _get_guest_xml xml= 3d6a16d5-6678-474e-9710-682473d1d98c instance-00000001 524288 1 vm1 2015-09-26 12:52:12 512 1 0 0 1 admin demo OpenStack Foundation OpenStack Nova 12.0.0 464493d4-7872-43c0-b9c2-5f5085d5dc5b 3d6a16d5-6678-474e-9710-682473d1d98c Virtual Machine hvm 1024  from (pid=2811) _get_guest_xml /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:4332 2015-09-26 08:52:12.802 DEBUG nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking state from (pid=2811) _get_power_state /home/stack/src/cloud/nova/nova/compute/manager.py:1328 2015-09-26 08:52:14.455 DEBUG nova.compute.manager [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Received event network-changed from (pid=2811) external_instance_event /home/stack/src/cloud/nova/nova/compute/manager.py:6376 2015-09-26 08:52:14.456 DEBUG oslo_concurrency.lockutils [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] Acquired semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:14.457 DEBUG nova.network.neutronv2.api [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _get_instance_nw_info() from (pid=2811) _get_instance_nw_info /home/stack/src/cloud/nova/nova/network/neutronv2/api.py:922 2015-09-26 08:52:14.489 DEBUG oslo_concurrency.lockutils [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:14.490 DEBUG oslo_concurrency.lockutils [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:14.491 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:14.656 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-62673df0-5584-4888-b648-a586b591657d RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack2", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:14.657 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/networks.json?id=c16b9c17-a4c6-41ec-adcc-2800accbb727 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}63b5ff8c3561146933098ebb9f44b37be371b5e5" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:14.825 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 454 x-openstack-request-id: req-4f5b1a38-6352-49d3-93ab-300ffae6f376 RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["ef534dcc-7e40-461c-865f-b64199d5a8a0", "288075d8-b675-44d1-a50b-8832986c7d96"], "name": "private", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mtu": 0, "router:external": false, "shared": false, "port_security_enabled": true, "provider:network_type": "vxlan", "id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "provider:segmentation_id": 1041}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:14.826 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=10.1.0.3&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:14.846 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-f01c160f-8712-4955-b230-f4c16e5f5674 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:14.847 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=fdbd%3A4e3b%3Ace09%3A0%3Af816%3A3eff%3Afe83%3A44aa&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:14.869 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-be6e821a-ae06-40fd-9755-916898c4d6be RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:14.870 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/subnets.json?id=288075d8-b675-44d1-a50b-8832986c7d96&id=ef534dcc-7e40-461c-865f-b64199d5a8a0 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}63b5ff8c3561146933098ebb9f44b37be371b5e5" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:14.929 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 964 x-openstack-request-id: req-ba965ead-cdee-4fcc-a733-6c0d106422e0 RESP BODY: {"subnets": [{"name": "private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "10.1.0.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "10.1.0.2", "end": "10.1.0.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "10.1.0.0/24", "id": "288075d8-b675-44d1-a50b-8832986c7d96", "subnetpool_id": null}, {"name": "ipv6-private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "fdbd:4e3b:ce09::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "fdbd:4e3b:ce09::2", "end": "fdbd:4e3b:ce09:0:ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "fdbd:4e3b:ce09::/64", "id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "subnetpool_id": null}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:14.930 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}63b5ff8c3561146933098ebb9f44b37be371b5e5" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:15.034 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-7994d591-6659-4b07-8f33-b4a3cfba82c2 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:15.036 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}63b5ff8c3561146933098ebb9f44b37be371b5e5" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:15.115 DEBUG keystoneclient.session [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] RESP: [200] date: Sat, 26 Sep 2015 12:52:14 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-4a02477e-9b36-48de-9d44-300f7e732ef1 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:15.117 DEBUG nova.network.base_api [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Updating instance_info_cache with network_info: [VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.1.0.3'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'meta': {}, 'version': 6, 'type': 'fixed', 'floating_ips': [], 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None})] from (pid=2811) update_instance_cache_with_nw_info /home/stack/src/cloud/nova/nova/network/base_api.py:43 2015-09-26 08:52:15.141 DEBUG oslo_concurrency.lockutils [req-09a789e6-139c-4ffa-bda5-a3ae9a0f6011 nova service] Releasing semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:16.386 DEBUG nova.compute.manager [req-4ab48438-31bc-4046-b783-a7b1aea2d306 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Received event network-vif-plugged-da4ab1e3-be0d-4c24-8a90-d863aa189577 from (pid=2811) external_instance_event /home/stack/src/cloud/nova/nova/compute/manager.py:6376 2015-09-26 08:52:16.387 DEBUG oslo_concurrency.lockutils [req-4ab48438-31bc-4046-b783-a7b1aea2d306 nova service] Lock "3d6a16d5-6678-474e-9710-682473d1d98c-events" acquired by "nova.compute.manager._pop_event" :: waited 0.000s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 08:52:16.387 DEBUG nova.compute.manager [req-4ab48438-31bc-4046-b783-a7b1aea2d306 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Unexpected attempt to pop events during shutdown from (pid=2811) _pop_event /home/stack/src/cloud/nova/nova/compute/manager.py:527 2015-09-26 08:52:16.388 DEBUG oslo_concurrency.lockutils [req-4ab48438-31bc-4046-b783-a7b1aea2d306 nova service] Lock "3d6a16d5-6678-474e-9710-682473d1d98c-events" released by "nova.compute.manager._pop_event" :: held 0.001s from (pid=2811) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 08:52:16.388 DEBUG nova.compute.manager [req-4ab48438-31bc-4046-b783-a7b1aea2d306 nova service] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] No waiting events found dispatching network-vif-plugged-da4ab1e3-be0d-4c24-8a90-d863aa189577 from (pid=2811) pop_instance_event /home/stack/src/cloud/nova/nova/compute/manager.py:543 2015-09-26 08:52:19.143 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:52:23.143 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager._poll_rebooting_instances from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:52:26.142 DEBUG oslo_service.periodic_task [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Running periodic task ComputeManager._heal_instance_info_cache from (pid=2811) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 08:52:26.142 DEBUG nova.compute.manager [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Starting heal instance info cache from (pid=2811) _heal_instance_info_cache /home/stack/src/cloud/nova/nova/compute/manager.py:5412 2015-09-26 08:52:26.143 DEBUG nova.compute.manager [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Rebuilding the list of instances to heal from (pid=2811) _heal_instance_info_cache /home/stack/src/cloud/nova/nova/compute/manager.py:5416 2015-09-26 08:52:26.202 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.203 DEBUG nova.network.neutronv2.api [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _get_instance_nw_info() from (pid=2811) _get_instance_nw_info /home/stack/src/cloud/nova/nova/network/neutronv2/api.py:922 2015-09-26 08:52:26.204 DEBUG nova.objects.instance [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Lazy-loading `info_cache' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=2811) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 08:52:26.301 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.302 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:26.303 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.395 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-d6cb2408-31ce-469f-aefe-a8377f09de17 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack2", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.396 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.397 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:26.397 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/networks.json?id=c16b9c17-a4c6-41ec-adcc-2800accbb727 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.436 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 454 x-openstack-request-id: req-54d98049-c920-4976-a060-cfe6b3a8ddb6 RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["288075d8-b675-44d1-a50b-8832986c7d96", "ef534dcc-7e40-461c-865f-b64199d5a8a0"], "name": "private", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mtu": 0, "router:external": false, "shared": false, "port_security_enabled": true, "provider:network_type": "vxlan", "id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "provider:segmentation_id": 1041}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.437 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=10.1.0.3&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.449 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-8abcf86b-bac9-4ee9-8a2b-ed5fe6acb056 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.450 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=fdbd%3A4e3b%3Ace09%3A0%3Af816%3A3eff%3Afe83%3A44aa&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.467 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-f9eb795a-e9b7-499f-894b-d2b29fae8513 RESP BODY: {"floatingips": []}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.468 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.469 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:26.470 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/subnets.json?id=288075d8-b675-44d1-a50b-8832986c7d96&id=ef534dcc-7e40-461c-865f-b64199d5a8a0 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.518 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 964 x-openstack-request-id: req-1e12ae25-cb8a-493f-b4a0-0ac4dae6f34e RESP BODY: {"subnets": [{"name": "private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "10.1.0.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "10.1.0.2", "end": "10.1.0.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "10.1.0.0/24", "id": "288075d8-b675-44d1-a50b-8832986c7d96", "subnetpool_id": null}, {"name": "ipv6-private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "fdbd:4e3b:ce09::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "fdbd:4e3b:ce09::2", "end": "fdbd:4e3b:ce09:0:ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "fdbd:4e3b:ce09::/64", "id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "subnetpool_id": null}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.519 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.520 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:26.521 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.623 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-b72c7169-3628-49fa-8625-3e8004c8a450 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=2811) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 08:52:26.624 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 08:52:26.625 DEBUG oslo_concurrency.lockutils [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=2811) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 08:52:26.626 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c1352f1d1baaa74f1a64a38d127d0dd3b76ab643" from (pid=2811) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 08:52:26.721 DEBUG keystoneclient.session [req-f8952808-bb0c-4052-ac05-720c0a7744b8 None None] RESP: [200] date: Sat, 26 Sep 2015 12:52:26 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-be9d024b-53c3-4539-a70b-cc453d1237a9 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_i