O02八、nova-compute 部署 instance 詳解

參考 http://www.javashuo.com/article/p-zwjnstjb-be.html

 

本節討論 nova-compute ，並詳細分析 instance 部署的全過程。

 

nova-compute 在計算節點上運行，負責管理節點上的instance 。OpenStack 對instance 的操做， 最後都是交給 nova-compute 來完成的。nova-compute 來完成的。nova-compute 與 Hypervisor 一塊兒實現 OpenStack 對 instance 聲明週期的管理。

 

經過 Driver 架構支持多種Hypervisor

 

接着的問題是：如今市面上那麼多 Hypervisor ，nova-compute 如何與他們配合呢？

 

 

這就是咱們以前討論的 Driver 架構。nova-compute 爲這些 Hypervisor 定義了統一的接口，Hypervisor 只須要實現這些接口，就能夠以 Driver 的形式即插即用到OpenStack 系統中。下面是Nova Driver 的架構示意圖：

 

 

咱們能夠在 /opt/stack/nova/nova/virt/目錄下查看到OpenStack 源代碼中已經自帶了上面這幾個Hypervisor的 Driver

 

stack@DevStack-Controller:~$ ll /opt/stack/nova/nova/virt/ | grep '^d'

drwxr-xr-x  9 stack stack     4096 May 22 01:12 ./

drwxr-xr-x 32 stack stack     4096 May 22 01:12 ../

drwxr-xr-x  4 stack stack     4096 May 22 01:12 disk/

drwxr-xr-x  2 stack stack     4096 May 22 00:55 hyperv/

drwxr-xr-x  2 stack stack     4096 May 22 01:12 image/

drwxr-xr-x  2 stack stack     4096 May 22 00:55 ironic/

drwxr-xr-x  4 stack stack     4096 May 22 01:12 libvirt/

drwxr-xr-x  2 stack stack     4096 May 22 00:55 vmwareapi/

drwxr-xr-x  3 stack stack     4096 May 22 00:55 xenapi/

 

某個特定的計算節點上只會運行一種 Hypervisor ，只須要在該節點 nova-compute 的配置文件 中指定 compute_driver  便可，由於咱們是用的是KVM，因此配置的是 libvirt 的driver

 

stack@DevStack-Controller:~$ cat /etc/nova/nova.conf | grep compute_driver

compute_driver = libvirt.LibvirtDriver

 

nova-compute 的功能能夠分爲兩類：

 

    一、定時向 OpenStack 報告計算節點的狀態

    二、實現 instance 生命週期的管理

 

按期向 OpenStack 報告計算節點的狀態

 

前面咱們看到 nova-scheduler 的不少 Filter 是根據計算節點的資源使用狀況進行過濾的。好比 RamFilter 要檢查計算節點當前可用的內存量。CoreFilter 檢查可用的 vCPU 數量。DiskFilter 則會檢查可用的磁盤空間。

 

那這裏有個問題：OpenStack 是如何得知每一個計算節點的這些信息呢？

 

答案就是：nova-compute 會按期向OpenStack 報告。從nova-compute 的日誌 /opt/stacklogs/n-cpu.log 能夠發現，每一個一段時間，nova-compute 就會報告當前計算節點的資源使用狀況 和 nova-compute 的服務狀態

 

2019-05-23 15:44:30.875 DEBUG nova.compute.resource_tracker [req-aceadd16-b754-4d7d-a373-504d946ed357 None None] Hypervisor/Node resource view: name=DevStack-Compute free_ram=15469MB free_disk=152GB free_vcpus=8

 

若是咱們再深刻問一個問題：nova-compute 是如何得到當前計算節點的資源使用信息呢？

 

要獲得計算節點的資源使用詳細狀況，須要知道當前節點上全部 instance 的資源佔用信息。nova-compute 經過 Hypervisor 的 driver 拿到這些信息。

 

好比咱們實驗環境使用的Hypervisor 是KVM，用的 driver 是 LibvirtDriver 。LibvirtDriver 能夠調用相關的API 得到資源信息，這些 API 的做用至關於咱們在CLI裏執行 virsh nodeinfo 、virsh dominfo 等命令。

 

實現 instance 生命週期的管理

 

OpenStack 對 instance 最主要的操做都是經過 nova-compute 實現的，包括 instance 的launch 、 shutdown、reboot、suspend 、 resume、terminate、resize、migration 、 snapshot等

 

本小節重點學習 nova-compute 如何實現 instance launch （部署） 操做，其餘操做將會在後的章節討論。

 

當 nova-scheduler 選定了部署 instance 的計算節點後，會經過消息中間件 RabbitMQ 向選定的計算節點發出 launch instance 的命令。該計算節點上運行的 nova-compute 收到消息後會執行 instance 建立操做。日誌 /opt/stack/logs/n-cpu.log 記錄了整個操做過程

 

nova-compute建立instance 的過程能夠分爲4步：

 

    一、爲instance 準備資源

    二、建立instance的鏡像文件

    三、建立 instance 的XML 定義文件

    四、建立虛擬網絡並啓動虛擬機

 

 

下面是instance admin-test03 的詳細信息和建立過程

 

 

2019-05-23 16:35:16.413 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec" acquired by "nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270

2019-05-23 16:35:16.430 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Starting instance... from (pid=4613) _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1766

2019-05-23 16:35:16.528 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Attempting claim: memory 256 MB, disk 0 GB, vcpus 1 CPU    #    在系統中分配資源（mem、cpu、disk）

2019-05-23 16:35:16.528 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Total memory: 16046 MB, used: 1024.00 MB    #    分配mem

2019-05-23 16:35:16.529 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] memory limit: 24069.00 MB, free: 23045.00 MB

2019-05-23 16:35:16.529 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Total disk: 155 GB, used: 0.00 GB    #    分配disk

2019-05-23 16:35:16.529 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] disk limit: 155.00 GB, free: 155.00 GB

2019-05-23 16:35:16.530 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Total vcpu: 8 VCPU, used: 2.00 VCPU    #    分配cpu

2019-05-23 16:35:16.530 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] vcpu limit not specified, defaulting to unlimited

2019-05-23 16:35:16.531 INFO nova.compute.claims [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Claim successful    #    分配成功

2019-05-23 16:35:16.669 DEBUG nova.scheduler.client.report [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Sending allocation for instance {'MEMORY_MB': 256, 'VCPU': 1} from (pid=4613) _allocate_for_instance /opt/stack/nova/nova/scheduler/client/report.py:664

2019-05-23 16:35:16.722 INFO nova.scheduler.client.report [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Submitted allocation for instance

2019-05-23 16:35:16.861 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Start building networks asynchronously for instance. from (pid=4613) _build_resources /opt/stack/nova/nova/compute/manager.py:2083

2019-05-23 16:35:16.963 WARNING nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Ignoring supplied device name: /dev/vda. Libvirt can't honour user-supplied dev names

2019-05-23 16:35:16.968 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Allocating IP information in the background. from (pid=4613) _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1398

2019-05-23 16:35:16.969 DEBUG nova.network.neutronv2.api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] allocate_for_instance() from (pid=4613) allocate_for_instance /opt/stack/nova/nova/network/neutronv2/api.py:840

2019-05-23 16:35:16.997 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Start building block device mappings for instance. from (pid=4613) _build_resources /opt/stack/nova/nova/compute/manager.py:2109

2019-05-23 16:35:17.086 INFO nova.virt.block_device [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Booting with blank volume at /dev/vda

2019-05-23 16:35:17.919 DEBUG nova.network.neutronv2.api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Successfully created port: ef41d30d-862f-4342-919a-95ed7a0587e3 from (pid=4613) _create_port_minimal /opt/stack/nova/nova/network/neutronv2/api.py:407

2019-05-23 16:35:18.922 DEBUG nova.network.neutronv2.api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Successfully updated port: ef41d30d-862f-4342-919a-95ed7a0587e3 from (pid=4613) _update_port /opt/stack/nova/nova/network/neutronv2/api.py:444

2019-05-23 16:35:18.964 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Acquired semaphore "refresh_cache-a0e2b485-f40c-43e4-beb6-049b6399f0ec" from (pid=4613) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212

2019-05-23 16:35:18.965 DEBUG nova.network.neutronv2.api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] _get_instance_nw_info() from (pid=4613) _get_instance_nw_info /opt/stack/nova/nova/network/neutronv2/api.py:1295

2019-05-23 16:35:19.054 DEBUG nova.compute.manager [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Received event network-changed from (pid=4613) external_instance_event /opt/stack/nova/nova/compute/manager.py:6900

2019-05-23 16:35:19.059 DEBUG neutronclient.v2_0.client [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] GET call to neutron for http://10.12.31.241:9696/v2.0/ports.json?tenant_id=c2b9e5f4a15d43218f3fca6e13c49a3a&device_id=a0e2b485-f40c-43e4-beb6-049b6399f0ec used request id req-02170a5f-ad8c-46bd-a0d7-a87a0369f578 from (pid=4613) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128

2019-05-23 16:35:19.060 DEBUG nova.network.neutronv2.api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Instance cache missing network info. from (pid=4613) _get_preexisting_port_ids /opt/stack/nova/nova/network/neutronv2/api.py:2194

2019-05-23 16:35:19.285 DEBUG cinderclient.v2.client [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] REQ: curl -g -i -X POST http://10.12.31.241:8776/v2/c2b9e5f4a15d43218f3fca6e13c49a3a/volumes/2ba40932-cabc-40b1-9011-87354ac29fc1/action -H "User-Agent: python-cinderclient" -H "Content-Type: application/json" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}b6ab852c24e900a76c48a07b9d95e71bebefd129" -d '{"os-attach": {"instance_uuid": "a0e2b485-f40c-43e4-beb6-049b6399f0ec", "mountpoint": "/dev/vda", "mode": "rw"}}' from (pid=4613) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:347

2019-05-23 16:35:19.476 DEBUG nova.network.base_api [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Updating instance_info_cache with network_info: [{"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null}] from (pid=4613) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:48

2019-05-23 16:35:19.529 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Releasing semaphore "refresh_cache-a0e2b485-f40c-43e4-beb6-049b6399f0ec" from (pid=4613) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225

2019-05-23 16:35:19.529 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Instance network_info: |[{"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null}]| from (pid=4613) _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1413

2019-05-23 16:35:19.531 DEBUG oslo_concurrency.lockutils [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] Acquired semaphore "refresh_cache-a0e2b485-f40c-43e4-beb6-049b6399f0ec" from (pid=4613) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212

2019-05-23 16:35:19.531 DEBUG nova.network.neutronv2.api [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] _get_instance_nw_info() from (pid=4613) _get_instance_nw_info /opt/stack/nova/nova/network/neutronv2/api.py:1295

2019-05-23 16:35:19.621 DEBUG neutronclient.v2_0.client [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] GET call to neutron for http://10.12.31.241:9696/v2.0/ports.json?tenant_id=c2b9e5f4a15d43218f3fca6e13c49a3a&device_id=a0e2b485-f40c-43e4-beb6-049b6399f0ec used request id req-4974104b-dd47-4e3c-a361-5af0216b77a9 from (pid=4613) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128

2019-05-23 16:35:19.742 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Start spawning the instance on the hypervisor. from (pid=4613) _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1942

2019-05-23 16:35:19.743 INFO nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Creating image

2019-05-23 16:35:20.017 DEBUG nova.network.base_api [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Updating instance_info_cache with network_info: [{"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null}] from (pid=4613) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:48

2019-05-23 16:35:20.028 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/013ffe0108c53d3e6a35423faf2481a9302c34aa /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/kernel from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355

2019-05-23 16:35:20.038 DEBUG oslo_concurrency.lockutils [req-d3b1fdc5-9b3b-4d58-9a28-56aec0caf773 service nova] Releasing semaphore "refresh_cache-a0e2b485-f40c-43e4-beb6-049b6399f0ec" from (pid=4613) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225

2019-05-23 16:35:20.040 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] CMD " cp -r /opt/stack/data/nova/instances/_base/013ffe0108c53d3e6a35423faf2481a9302c34aa /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/kernel" returned: 0 in 0.012s from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385

2019-05-23 16:35:20.041 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/kernel from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355

2019-05-23 16:35:20.092 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/kernel" returned: 0 in 0.051s from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385

2019-05-23 16:35:20.093 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270

2019-05-23 16:35:20.098 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.005s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

2019-05-23 16:35:20.355 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/aee1333f1c105e7dafde694cd2bb73d547b6598d /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/ramdisk from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355

2019-05-23 16:35:20.367 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] CMD " cp -r /opt/stack/data/nova/instances/_base/aee1333f1c105e7dafde694cd2bb73d547b6598d /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/ramdisk" returned: 0 in 0.011s from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385

2019-05-23 16:35:20.368 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/ramdisk from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:355

2019-05-23 16:35:20.420 DEBUG oslo_concurrency.processutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/ramdisk" returned: 0 in 0.052s from (pid=4613) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:385

2019-05-23 16:35:20.421 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270

2019-05-23 16:35:20.422 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

2019-05-23 16:35:20.422 DEBUG nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Ensure instance console log exists: /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/console.log from (pid=4613) _ensure_console_log_for_instance /opt/stack/nova/nova/virt/libvirt/driver.py:3061

2019-05-23 16:35:20.425 DEBUG nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Start _get_guest_xml network_info=[{"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null}] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {u'/dev/vda': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}, 'root': {'bus': u'virtio', 'boot_index': '1', 'type': u'disk', 'dev': u'vda'}}} image_meta=ImageMeta(checksum='eb9139e4942121f22bbc2afc0400b2a4',container_format='ami',created_at=2019-05-21T17:11:20Z,direct_url=<?>,disk_format='ami',id=7c5fbab9-c215-47db-9848-66ca5305f0ac,min_disk=0,min_ram=0,name='cirros-0.3.4-x86_64-uec',owner='c2b9e5f4a15d43218f3fca6e13c49a3a',properties=ImageMetaProps,protected=<?>,size=25165824,status='active',tags=<?>,updated_at=2019-05-21T17:11:20Z,virtual_size=<?>,visibility=<?>) rescue=None block_device_info={'swap': None, 'root_device_name': u'/dev/vda', 'ephemerals': [], 'block_device_mapping': [{'guest_format': None, 'boot_index': 0, 'mount_device': u'/dev/vda', 'connection_info': {u'driver_volume_type': u'iscsi', 'connector': {'platform': 'x86_64', 'host': 'DevStack-Controller', 'do_local_attach': False, 'ip': '10.12.31.241', 'os_type': 'linux2', 'multipath': False, 'initiator': u'iqn.1993-08.org.debian:01:1997f5bacda'}, 'serial': u'2ba40932-cabc-40b1-9011-87354ac29fc1', u'data': {u'access_mode': u'rw', u'target_discovered': False, u'encrypted': False, u'qos_specs': None, u'target_iqn': u'iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1', u'target_portal': u'10.12.31.241:3260', u'volume_id': u'2ba40932-cabc-40b1-9011-87354ac29fc1', u'target_lun': 1, u'auth_password': u'***', u'auth_username': u'Nto8maSrg6QoWcwQ6bQ7', u'auth_method': u'CHAP'}}, 'disk_bus': u'virtio', 'device_type': u'disk', 'delete_on_termination': False}]} from (pid=4613) _get_guest_xml /opt/stack/nova/nova/virt/libvirt/driver.py:5062

2019-05-23 16:35:21.882 DEBUG nova.virt.libvirt.vif [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2019-05-23T08:34:42Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='admin-test03',display_name='admin-test03',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(1),host='DevStack-Controller',hostname='admin-test03',id=3,image_ref='',info_cache=InstanceInfoCache,instance_type_id=1,kernel_id='c3f9bfb6-f089-4a0a-b410-e128284761f8',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='DevStack-Controller',locked=False,locked_by=None,memory_mb=256,metadata={},migration_context=<?>,new_flavor=None,node='DevStack-Controller',numa_topology=None,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='c2b9e5f4a15d43218f3fca6e13c49a3a',ramdisk_id='16b087bd-8aa5-48fa-968b-6d8986ee2434',reservation_id='r-m4xc1dvw',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='admin',image_base_image_ref='',image_container_format='ami',image_disk_format='ami',image_kernel_id='c3f9bfb6-f089-4a0a-b410-e128284761f8',image_min_disk='0',image_min_ram='0',image_ramdisk_id='16b087bd-8aa5-48fa-968b-6d8986ee2434',network_allocated='True',owner_project_name='admin',owner_user_name='admin'},tags=<?>,task_state='spawning',terminated_at=None,updated_at=2019-05-23T08:35:17Z,user_data=None,user_id='c23652fbcaa74c1e8becc960e2210820',uuid=a0e2b485-f40c-43e4-beb6-049b6399f0ec,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null} virt_type=kvm from (pid=4613) get_config /opt/stack/nova/nova/virt/libvirt/vif.py:529

2019-05-23 16:35:21.891 DEBUG nova.objects.instance [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lazy-loading 'pci_devices' on Instance uuid a0e2b485-f40c-43e4-beb6-049b6399f0ec from (pid=4613) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1058

2019-05-23 16:35:21.902 DEBUG nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] End _get_guest_xml xml=<domain type="kvm">

  <uuid>a0e2b485-f40c-43e4-beb6-049b6399f0ec</uuid>

  <name>instance-00000003</name>

  <memory>262144</memory>

  <vcpu>1</vcpu>

  <metadata>

    <nova:instance xmlns:nova="http://openstack.org/xmlns/libvirt/nova/1.0">

      <nova:package version="15.1.6"/>

      <nova:name>admin-test03</nova:name>

      <nova:creationTime>2019-05-23 08:35:20</nova:creationTime>

      <nova:flavor name="cirros256">

        <nova:memory>256</nova:memory>

        <nova:disk>0</nova:disk>

        <nova:swap>0</nova:swap>

        <nova:ephemeral>0</nova:ephemeral>

        <nova:vcpus>1</nova:vcpus>

      </nova:flavor>

      <nova:owner>

        <nova:user uuid="c23652fbcaa74c1e8becc960e2210820">admin</nova:user>

        <nova:project uuid="c2b9e5f4a15d43218f3fca6e13c49a3a">admin</nova:project>

      </nova:owner>

    </nova:instance>

  </metadata>

  <sysinfo type="smbios">

    <system>

      <entry name="manufacturer">OpenStack Foundation</entry>

      <entry name="product">OpenStack Nova</entry>

      <entry name="version">15.1.6</entry>

      <entry name="serial">89b90ae8-bc53-f0dd-6f7c-57a35ce3f8ab</entry>

      <entry name="uuid">a0e2b485-f40c-43e4-beb6-049b6399f0ec</entry>

      <entry name="family">Virtual Machine</entry>

    </system>

  </sysinfo>

  <os>

    <type>hvm</type>

    <kernel>/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/kernel</kernel>

    <initrd>/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/ramdisk</initrd>

    <cmdline>root=/dev/vda console=tty0 console=ttyS0</cmdline>

    <smbios mode="sysinfo"/>

  </os>

  <features>

    <acpi/>

    <apic/>

  </features>

  <cputune>

    <shares>1024</shares>

  </cputune>

  <clock offset="utc">

    <timer name="pit" tickpolicy="delay"/>

    <timer name="rtc" tickpolicy="catchup"/>

    <timer name="hpet" present="no"/>

  </clock>

  <cpu match="exact">

    <topology sockets="1" cores="1" threads="1"/>

  </cpu>

  <devices>

    <disk type="block" device="disk">

      <driver name="qemu" type="raw" cache="none" io="native"/>

      <source dev="/dev/disk/by-path/ip-10.12.31.241:3260-iscsi-iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1-lun-1"/>

      <target bus="virtio" dev="vda"/>

      <serial>2ba40932-cabc-40b1-9011-87354ac29fc1</serial>

    </disk>

    <interface type="bridge">

      <mac address="fa:16:3e:7c:d6:21"/>

      <model type="virtio"/>

      <source bridge="brq32740d6a-81"/>

      <target dev="tapef41d30d-86"/>

    </interface>

    <serial type="pty">

      <log file="/opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec/console.log" append="off"/>

    </serial>

    <graphics type="vnc" autoport="yes" keymap="en-us" listen="127.0.0.1"/>

    <video>

      <model type="cirrus"/>

    </video>

    <memballoon model="virtio">

      <stats period="10"/>

    </memballoon>

  </devices>

</domain>

2019-05-23 16:35:21.902 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Preparing to wait for external event network-vif-plugged-ef41d30d-862f-4342-919a-95ed7a0587e3 from (pid=4613) prepare_for_instance_event /opt/stack/nova/nova/compute/manager.py:328

2019-05-23 16:35:21.902 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec-events" acquired by "nova.compute.manager._create_or_get_event" :: waited 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270

2019-05-23 16:35:21.903 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec-events" released by "nova.compute.manager._create_or_get_event" :: held 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

2019-05-23 16:35:21.903 DEBUG nova.virt.libvirt.vif [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2019-05-23T08:34:42Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='admin-test03',display_name='admin-test03',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(1),host='DevStack-Controller',hostname='admin-test03',id=3,image_ref='',info_cache=InstanceInfoCache,instance_type_id=1,kernel_id='c3f9bfb6-f089-4a0a-b410-e128284761f8',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='DevStack-Controller',locked=False,locked_by=None,memory_mb=256,metadata={},migration_context=<?>,new_flavor=None,node='DevStack-Controller',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='c2b9e5f4a15d43218f3fca6e13c49a3a',ramdisk_id='16b087bd-8aa5-48fa-968b-6d8986ee2434',reservation_id='r-m4xc1dvw',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='admin',image_base_image_ref='',image_container_format='ami',image_disk_format='ami',image_kernel_id='c3f9bfb6-f089-4a0a-b410-e128284761f8',image_min_disk='0',image_min_ram='0',image_ramdisk_id='16b087bd-8aa5-48fa-968b-6d8986ee2434',network_allocated='True',owner_project_name='admin',owner_user_name='admin'},tags=<?>,task_state='spawning',terminated_at=None,updated_at=2019-05-23T08:35:17Z,user_data=None,user_id='c23652fbcaa74c1e8becc960e2210820',uuid=a0e2b485-f40c-43e4-beb6-049b6399f0ec,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"profile": {}, "ovs_interfaceid": null, "preserve_on_delete": false, "network": {"bridge": "brq32740d6a-81", "subnets": [{"ips": [{"meta": {}, "version": 6, "type": "fixed", "floating_ips": [], "address": "2001:db8::3"}], "version": 6, "meta": {}, "dns": [], "routes": [], "cidr": "2001:db8::/64", "gateway": {"meta": {}, "version": 6, "type": "gateway", "address": "2001:db8::2"}}, {"ips": [{"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "172.24.4.16"}], "version": 4, "meta": {}, "dns": [], "routes": [], "cidr": "172.24.4.0/24", "gateway": {"meta": {}, "version": 4, "type": "gateway", "address": "172.24.4.1"}}], "meta": {"injected": false, "tenant_id": "c2b9e5f4a15d43218f3fca6e13c49a3a", "should_create_bridge": true, "mtu": 1500}, "id": "32740d6a-8119-4c8e-9828-fe5da5b6e7ac", "label": "public"}, "devname": "tapef41d30d-86", "vnic_type": "normal", "qbh_params": null, "meta": {}, "details": {"port_filter": true}, "address": "fa:16:3e:7c:d6:21", "active": false, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null} from (pid=4613) plug /opt/stack/nova/nova/virt/libvirt/vif.py:776

2019-05-23 16:35:23.274 DEBUG nova.compute.manager [req-35ca125d-7c8a-47f3-800e-c5aa180488b1 service nova] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Received event network-vif-plugged-ef41d30d-862f-4342-919a-95ed7a0587e3 from (pid=4613) external_instance_event /opt/stack/nova/nova/compute/manager.py:6900

2019-05-23 16:35:23.275 DEBUG oslo_concurrency.lockutils [req-35ca125d-7c8a-47f3-800e-c5aa180488b1 service nova] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec-events" acquired by "nova.compute.manager._pop_event" :: waited 0.000s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270

2019-05-23 16:35:23.276 DEBUG oslo_concurrency.lockutils [req-35ca125d-7c8a-47f3-800e-c5aa180488b1 service nova] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec-events" released by "nova.compute.manager._pop_event" :: held 0.001s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

2019-05-23 16:35:23.276 DEBUG nova.compute.manager [req-35ca125d-7c8a-47f3-800e-c5aa180488b1 service nova] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Processing event network-vif-plugged-ef41d30d-862f-4342-919a-95ed7a0587e3 from (pid=4613) _process_instance_event /opt/stack/nova/nova/compute/manager.py:6855

2019-05-23 16:35:24.054 DEBUG nova.virt.driver [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] Emitting event <LifecycleEvent: 1558600524.05, a0e2b485-f40c-43e4-beb6-049b6399f0ec => Started> from (pid=4613) emit_event /opt/stack/nova/nova/virt/driver.py:1444

2019-05-23 16:35:24.055 INFO nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] VM Started (Lifecycle Event)

2019-05-23 16:35:24.061 DEBUG nova.virt.libvirt.driver [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Instance is running from (pid=4613) spawn /opt/stack/nova/nova/virt/libvirt/driver.py:2799

2019-05-23 16:35:24.064 INFO nova.virt.libvirt.driver [-] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Instance spawned successfully.

2019-05-23 16:35:24.065 INFO nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Took 4.32 seconds to spawn the instance on the hypervisor.

2019-05-23 16:35:24.065 DEBUG nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Checking state from (pid=4613) _get_power_state /opt/stack/nova/nova/compute/manager.py:1184

2019-05-23 16:35:24.094 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Checking state from (pid=4613) _get_power_state /opt/stack/nova/nova/compute/manager.py:1184

2019-05-23 16:35:24.102 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Synchronizing instance power state after lifecycle event "Started"; current vm_state: building, current task_state: spawning, current DB power_state: 0, VM power_state: 1 from (pid=4613) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1096

2019-05-23 16:35:24.142 INFO nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] During sync_power_state the instance has a pending task (spawning). Skip.

2019-05-23 16:35:24.142 DEBUG nova.virt.driver [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] Emitting event <LifecycleEvent: 1558600524.06, a0e2b485-f40c-43e4-beb6-049b6399f0ec => Paused> from (pid=4613) emit_event /opt/stack/nova/nova/virt/driver.py:1444

2019-05-23 16:35:24.143 INFO nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] VM Paused (Lifecycle Event)

2019-05-23 16:35:24.195 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Checking state from (pid=4613) _get_power_state /opt/stack/nova/nova/compute/manager.py:1184

2019-05-23 16:35:24.199 DEBUG nova.virt.driver [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] Emitting event <LifecycleEvent: 1558600524.06, a0e2b485-f40c-43e4-beb6-049b6399f0ec => Resumed> from (pid=4613) emit_event /opt/stack/nova/nova/virt/driver.py:1444

2019-05-23 16:35:24.200 INFO nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] VM Resumed (Lifecycle Event)

2019-05-23 16:35:24.227 INFO nova.compute.manager [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Took 7.72 seconds to build instance.

2019-05-23 16:35:24.239 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Checking state from (pid=4613) _get_power_state /opt/stack/nova/nova/compute/manager.py:1184

2019-05-23 16:35:24.243 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Synchronizing instance power state after lifecycle event "Resumed"; current vm_state: active, current task_state: None, current DB power_state: 1, VM power_state: 1 from (pid=4613) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1096

2019-05-23 16:35:24.248 DEBUG oslo_concurrency.lockutils [req-808daefa-2cd8-4c34-bd34-2730453805da admin admin] Lock "a0e2b485-f40c-43e4-beb6-049b6399f0ec" released by "nova.compute.manager._locked_do_build_and_run_instance" :: held 7.834s from (pid=4613) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

2019-05-23 16:35:24.281 DEBUG nova.virt.driver [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] Emitting event <LifecycleEvent: 1558600524.06, a0e2b485-f40c-43e4-beb6-049b6399f0ec => Resumed> from (pid=4613) emit_event /opt/stack/nova/nova/virt/driver.py:1444

2019-05-23 16:35:24.282 INFO nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] VM Resumed (Lifecycle Event)

2019-05-23 16:35:24.320 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Checking state from (pid=4613) _get_power_state /opt/stack/nova/nova/compute/manager.py:1184

2019-05-23 16:35:24.323 DEBUG nova.compute.manager [req-716d3f56-c88c-4ae8-ae98-166a6848a639 None None] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Synchronizing instance power state after lifecycle event "Resumed"; current vm_state: active, current task_state: None, current DB power_state: 1, VM power_state: 1 from (pid=4613) handle_lifecycle_event /opt/stack/nova/nova/compute/manager.py:1096

 

①爲instance準備資源

 

nova-compute 首選會根據指定的flavor 依次爲instance分配內存、磁盤、vCPU 、網絡

 

②建立instance的鏡像文件

 

資源準備好後，nova-Compute 會爲instance 建立鏡像文件。OpenStack 啓動一個instance 時，會選擇一個image ，這個image 由Glance 管理。nova-compute 會：

 

    一、首先將該image 下載 到計算節點

    二、而後將其做爲backing file 建立 instance 的鏡像文件

 

從Glance 下載image ，nova-compute 首先會檢查image是否已經下載（好比以前已經建立過相同image的instance）。若是沒有，就從Glance 下載image 到本地。由此開機按，若是計算節點上要運行多個相同的image的instance，只會在啓動第一個instance的時候從 Glance 下載 image，後面的instance 啓動速度會大大加快。

 

nova配置文件中定義了  instances_path = /opt/stack/data/nova/instances  虛機的磁盤文件、日誌文件等都存放在這裏

 

root@DevStack-Controller:/opt/stack/data/nova/instances# ll

total 32

drwxr-xr-x 7 stack root     4096 May 23 16:35 ./

drwxr-xr-x 4 stack root     4096 May 23 16:21 ../

drwxr-xr-x 2 stack libvirtd 4096 May 23 16:21 60958b71-e535-4241-a2a8-bf59c3e36abe/

drwxr-xr-x 2 stack libvirtd 4096 May 23 16:30 7b56d1e5-235e-4b95-a2fe-74017f744042/

drwxr-xr-x 2 stack libvirtd 4096 May 23 16:35 a0e2b485-f40c-43e4-beb6-049b6399f0ec/

drwxr-xr-x 2 stack libvirtd 4096 May 23 16:21 _base/

-rw-r--r-- 1 stack libvirtd   42 May 23 20:18 compute_nodes

drwxr-xr-x 2 stack libvirtd 4096 May 23 16:21 locks/

root@DevStack-Controller:/opt/stack/data/nova/instances# ll -h a0e2b485-f40c-43e4-beb6-049b6399f0ec/

total 8.4M

drwxr-xr-x 2 stack        libvirtd 4.0K May 23 16:35 ./

drwxr-xr-x 7 stack        root     4.0K May 23 16:35 ../

-rw------- 1 root         root      23K May 23 16:39 console.log

-rw-r--r-- 1 stack        libvirtd  172 May 23 16:35 disk.info

-rw-r--r-- 1 libvirt-qemu kvm      4.8M May 23 16:35 kernel

-rw-r--r-- 1 libvirt-qemu kvm      3.6M May 23 16:35 ramdisk

 

這裏有兩個容易混淆的術語：

 

    一、image ，指的是 Glance 上保存的鏡像，做爲instance 運行的模板，計算節點在須要的時候會將image下載到本地

    二、鏡像文件，指的是instance 啓動盤對應的文件

    三、英文中二者都叫 image ，爲了不混淆，咱們用image 和 鏡像文件區分

 

③建立instance的XML定義文件

 

④建立虛擬網絡並啓動 instance 

 

instance啓動後會按期檢查更新instance的狀態，最後咱們在命令行和web ui中均可以看到建立好的instance

 

 

---

下面的問題未解決

 

部署的OpenStack沒法建立instance，在instance詳情中能夠看到 「Host 'DevStack-Compute' is not mapped to any cell」

 

 

去DevStack-Controller節點上執行以下命令解決

 

stack@DevStack-Controller:~$ nova-manage cell_v2 discover_hosts

/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py:166: Warning: (1287, u"'@@tx_isolation' is deprecated and will be removed in a future release. Please use '@@transaction_isolation' instead")

  result = self._query(query)

/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py:166: Warning: (3090, u"Changing sql mode 'NO_AUTO_CREATE_USER' is deprecated. It will be removed in a future release.")

  result = self._query(query)

stack@DevStack-Controller:~$ nova-manage cell_v2 discover_hosts --verbose

/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py:166: Warning: (1287, u"'@@tx_isolation' is deprecated and will be removed in a future release. Please use '@@transaction_isolation' instead")

  result = self._query(query)

/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py:166: Warning: (3090, u"Changing sql mode 'NO_AUTO_CREATE_USER' is deprecated. It will be removed in a future release.")

  result = self._query(query)

Found 2 cell mappings.

Skipping cell0 since it does not contain hosts.

Getting compute nodes from cell: 5fd8cdfc-e20e-46da-8c1a-88e1c5ce2790

Found 2 computes in cell: 5fd8cdfc-e20e-46da-8c1a-88e1c5ce2790

Checking host mapping for compute host 'DevStack-Controller': 3ead96c5-1460-4573-8154-15b6727c1178

Checking host mapping for compute host 'DevStack-Compute': 00572519-253c-4d4e-843b-c4baceaf0a3b

 

執行完以上命令後 能夠建立instance了，可是隻能建立到 DevStack-Controller 上，禁用 DevStack-Controller 的nova後，再建立instance報錯

 

 

而後去 DevStack-Compute上執行命令

 

stack@DevStack-Compute:~$ source devstack/openrc admin admin

WARNING: setting legacy OS_TENANT_NAME to support cli tools.

stack@DevStack-Compute:~$ nova-manage cell_v2 discover_hosts --verbose

An error has occurred:

Traceback (most recent call last):

  File "/opt/stack/nova/nova/cmd/manage.py", line 1682, in main

    ret = fn(*fn_args, **fn_kwargs)

  File "/opt/stack/nova/nova/cmd/manage.py", line 1416, in discover_hosts

    hosts = host_mapping_obj.discover_hosts(ctxt, cell_uuid, status_fn)

  File "/opt/stack/nova/nova/objects/host_mapping.py", line 184, in discover_hosts

    cell_mappings = objects.CellMappingList.get_all(ctxt)

  File "/usr/local/lib/python2.7/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper

    result = fn(cls, context, *args, **kwargs)

  File "/opt/stack/nova/nova/objects/cell_mapping.py", line 127, in get_all

    db_mappings = cls._get_all_from_db(context)

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 893, in wrapper

    with self._transaction_scope(context):

  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__

    return self.gen.next()

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 944, in _transaction_scope

    allow_async=self._allow_async) as resource:

  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__

    return self.gen.next()

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 558, in _session

    bind=self.connection, mode=self.mode)

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 317, in _create_session

    self._start()

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 403, in _start

    engine_args, maker_args)

  File "/usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/enginefacade.py", line 425, in _setup_for_connection

    "No sql_connection parameter is established")

CantStartEngineError: No sql_connection parameter is established