[OpenStack] 创建实例的流程

本文最近更新于 2018 年 07 月 06 日

首先通过 OpenStack dashboard 创建一个 instance 实例，记下开始和结束时间，例如我的开始和结束时间是 2017-06-22 13:39:55 - 2017-06-22 13:42:28。

结束后，抓取 OpenStack 的相关 log。例如本文抓取的 log 有：

/var/log/cinder/volume.log
/var/log/neutron/server.log
/var/log/neutron/openvswitch-agent.log
/var/log/keystone/keystone.log
/var/log/nova-api.log
/var/log/nova-compute.log
/var/log/nova-conductor.log
/var/log/nova-scheduler.log

为了更好地通过 log 理解实例化的过程，对 log 进行一点加工：合并上述 log，然后按照时间顺序排列，我合并后的 log 链接：link

由于之前有一些 OpenStack dashboard 的其他操作，所以实例化的 log 从第 45 行开始：

2017-06-22 13:41:15.165 8861 INFO keystone.common.wsgi [req-f21a8942-22cb-4fc0-afd4-76ba79c02a0f - - - - -] POST https://10.0.2.15:5000/v3/auth/tokens
2017-06-22 13:41:15.704 3967 INFO neutron.wsgi [req-561bfcea-63b9-4b17-bcd8-99bf94bc2cb8 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:15] "GET /v2.0/ports.json?device_id=f9cc7dc5-949e-467e-b1c5-6453d6e0c47f HTTP/1.1" 200 211 0.283738
2017-06-22 13:41:15.793 4096 INFO nova.osapi_compute.wsgi.server [req-129269da-c369-4f4b-8dd3-cff6a0cb942d 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] 10.0.2.15 "GET /v2.1/355c595975894e7d8caa9c3af1ad3cb7/servers/f9cc7dc5-949e-467e-b1c5-6453d6e0c47f HTTP/1.1" status: 200 len: 1542 time: 0.6238599
2017-06-22 13:41:16.096 4096 INFO nova.osapi_compute.wsgi.server [req-20292c0a-b725-4c13-b720-7a1da024f5d5 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] 10.0.2.15 "GET /v2.1/355c595975894e7d8caa9c3af1ad3cb7/flavors/detail HTTP/1.1" status: 200 len: 2403 time: 0.1918740
2017-06-22 13:41:16.426 8860 INFO keystone.common.wsgi [req-1f2493aa-9e1a-4eaf-ab7c-64fabc3bfa60 525ea601affb42ba82c84fd1ac7f69f6 577fe7d4ac0346a1976335dc7400c65d - default default] GET https://10.0.2.15:35357/v3/auth/tokens
2017-06-22 13:41:17.745 8860 INFO keystone.common.wsgi [req-d8e418c0-e4b9-45b3-b4d9-edae5ab15777 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - default default] GET https://10.0.2.15:35357/v3/auth/tokens
2017-06-22 13:41:18.844 3967 INFO neutron.wsgi [req-e396f909-f6d5-484f-9caa-6105f58bd3e9 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:18] "GET /v2.0/ports.json?device_id=f9cc7dc5-949e-467e-b1c5-6453d6e0c47f HTTP/1.1" 200 211 1.798780

上述的 log 说明 keystone 开始请求 token，取得 token 之后，nova 开始发送 instance 实例请求（55-62 行）：

2017-06-22 13:41:18.913 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Attempting claim: memory 512 MB, disk 1 GB, vcpus 1 CPU
2017-06-22 13:41:18.914 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Total memory: 7823 MB, used: 512.00 MB
2017-06-22 13:41:18.915 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] memory limit: 11734.50 MB, free: 11222.50 MB
2017-06-22 13:41:18.916 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Total disk: 49 GB, used: 0.00 GB
2017-06-22 13:41:18.916 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Total vcpu: 1 VCPU, used: 0.00 VCPU
2017-06-22 13:41:18.916 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] disk limit: 49.00 GB, free: 49.00 GB
2017-06-22 13:41:18.917 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Claim successful
2017-06-22 13:41:18.917 3610 INFO nova.compute.claims [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] vcpu limit: 16.00 VCPU, free: 16.00 VCPU

之后 Nova Scheduler 开始为 instance 实例分配资源（68 行）：

2017-06-22 13:41:19.753 3610 INFO nova.scheduler.client.report [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Submitted allocation for instance

Glance 开始创建 volume 和 下载 image（91, 92 行）：

2017-06-22 13:41:29.923 3958 INFO cinder.volume.flows.manager.create_volume [req-e090c93f-aa81-4a80-b77e-d3072a983248 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Volume 4e248f95-5d7a-4a9d-9675-780acfc5246d: being created as image with specification: {'status': u'creating', 'image_location': (None, None), 'volume_size': 1, 'volume_name': 'volume-4e248f95-5d7a-4a9d-9675-780acfc5246d', 'image_id': 'eb94652f-4764-4ec9-baca-499e181eb91b', 'image_service': <cinder.image.glance.GlanceImageService object at 0x7c4a610>, 'image_meta': {'status': u'active', 'name': u'cirros', 'deleted': False, 'container_format': u'bare', 'created_at': datetime.datetime(2017, 5, 24, 18, 41, 41, tzinfo=<iso8601.Utc>), 'disk_format': u'qcow2', 'updated_at': datetime.datetime(2017, 5, 24, 18, 41, 41, tzinfo=<iso8601.Utc>), 'id': u'eb94652f-4764-4ec9-baca-499e181eb91b', 'owner': u'577fe7d4ac0346a1976335dc7400c65d', 'protected': False, 'min_ram': 0, 'checksum': u'ee1eca47dc88f4879d8a229cc70a07c6', 'min_disk': 0, 'is_public': True, 'deleted_at': None, 'properties': {}, 'size': 13287936}}
2017-06-22 13:41:30.198 3958 INFO cinder.image.image_utils [req-e090c93f-aa81-4a80-b77e-d3072a983248 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Image download 12.00 MB at 12.00 MB/s

Nova Compute 确认资源信息（100 行）：

2017-06-22 13:41:33.800 3610 INFO nova.compute.resource_tracker [req-1b587592-ffe5-4aa0-b635-fb4994ee6eae - - - - -] Final resource view: name=localhost.localdomain phys_ram=7823MB used_ram=1024MB phys_disk=49GB used_disk=1GB total_vcpus=1 used_vcpus=1 pci_stats=[]

Glance 转换 image（103 行）：

2017-06-22 13:41:37.221 3958 INFO cinder.image.image_utils [req-e090c93f-aa81-4a80-b77e-d3072a983248 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Converted 39.00 MB image at 24.02 MB/s

volume 创建完成（108, 109 行）：

2017-06-22 13:41:39.767 3958 INFO cinder.volume.flows.manager.create_volume [req-e090c93f-aa81-4a80-b77e-d3072a983248 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Volume volume-4e248f95-5d7a-4a9d-9675-780acfc5246d (4e248f95-5d7a-4a9d-9675-780acfc5246d): created successfully
2017-06-22 13:41:39.771 3958 INFO cinder.volume.manager [req-e090c93f-aa81-4a80-b77e-d3072a983248 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Created volume successfully.

Neutron 获取网络信息，决定虚拟机网络模式及建立网络连接：

2017-06-22 13:41:41.584 3967 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'code': 200, u'name': u'network-changed', u'server_uuid': u'f9cc7dc5-949e-467e-b1c5-6453d6e0c47f'}
2017-06-22 13:41:42.131 3967 INFO neutron.wsgi [req-0434e009-eb66-4d1e-9a8d-b7a086a66b9a 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:42] "GET /v2.0/ports.json?device_id=f9cc7dc5-949e-467e-b1c5-6453d6e0c47f HTTP/1.1" 200 1123 0.546784
2017-06-22 13:41:42.134 3967 INFO neutron.wsgi [req-f192d79e-b02f-4d1c-ad4f-7884b7f38259 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - - -] 10.0.2.15 - - [22/Jun/2017 13:41:42] "GET /v2.0/ports.json?tenant_id=355c595975894e7d8caa9c3af1ad3cb7&device_id=f9cc7dc5-949e-467e-b1c5-6453d6e0c47f HTTP/1.1" 200 1123 1.403762
2017-06-22 13:41:42.426 3967 INFO neutron.wsgi [req-392e08f1-366d-469f-b300-e99902a1d267 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:42] "GET /v2.0/floatingips.json?tenant_id=355c595975894e7d8caa9c3af1ad3cb7&port_id=a9aa6dee-2bf1-4e97-a5a2-e5a58e1d57c3 HTTP/1.1" 200 217 0.154877
2017-06-22 13:41:43.403 3967 INFO neutron.wsgi [req-58dfcd83-da0e-417d-9fbe-dc47210a3681 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - - -] 10.0.2.15 - - [22/Jun/2017 13:41:43] "GET /v2.0/networks.json?id=12f45958-2c36-48bb-ac47-9532ac2d07e4 HTTP/1.1" 200 905 1.238698
2017-06-22 13:41:43.586 3967 INFO neutron.wsgi [req-ca073ca3-715c-4422-b3ad-293502a74e33 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - - -] 10.0.2.15 - - [22/Jun/2017 13:41:43] "GET /v2.0/floatingips.json?fixed_ip_address=172.24.4.12&port_id=a9aa6dee-2bf1-4e97-a5a2-e5a58e1d57c3 HTTP/1.1" 200 217 0.175309
2017-06-22 13:41:43.759 3967 INFO neutron.wsgi [req-134e33b5-cebc-4aec-9119-89c6c78bb2d7 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:43] "GET /v2.0/ports.json?tenant_id=355c595975894e7d8caa9c3af1ad3cb7 HTTP/1.1" 200 1123 1.303612
2017-06-22 13:41:44.427 3958 INFO cinder.volume.targets.lio [req-fb004f05-c2f1-4862-a848-93f5a0f9dc07 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Creating iscsi_target for volume: volume-4e248f95-5d7a-4a9d-9675-780acfc5246d
2017-06-22 13:41:45.020 3967 INFO neutron.wsgi [req-54e8d1a9-06b0-4134-933b-c79c7b834fbd 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:45] "GET /v2.0/networks.json?id=12f45958-2c36-48bb-ac47-9532ac2d07e4 HTTP/1.1" 200 905 1.198562
2017-06-22 13:41:45.828 3967 INFO neutron.wsgi [req-017b8a05-3746-48cf-bea2-220be353c30d 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - - -] 10.0.2.15 - - [22/Jun/2017 13:41:45] "GET /v2.0/subnets.json?id=c954be37-19a7-4baa-9a57-09e5d9027610 HTTP/1.1" 200 864 2.212559
2017-06-22 13:41:46.213 3967 INFO neutron.wsgi [req-01eeee17-de22-41ce-92b5-8b3033b2adf0 62e05e7360e347dab374f7e6ecd9373e 577fe7d4ac0346a1976335dc7400c65d - - -] 10.0.2.15 - - [22/Jun/2017 13:41:46] "GET /v2.0/ports.json?network_id=12f45958-2c36-48bb-ac47-9532ac2d07e4&device_owner=network%3Adhcp HTTP/1.1" 200 211 0.347741
2017-06-22 13:41:46.386 3967 INFO neutron.wsgi [req-20b7f963-f69b-469a-b622-643172311793 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:46] "GET /v2.0/subnets.json HTTP/1.1" 200 1509 1.341801
2017-06-22 13:41:46.544 3967 INFO neutron.wsgi [req-ecee6e5d-391f-4c42-8721-031678400ba8 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] 10.0.2.15 - - [22/Jun/2017 13:41:46] "GET /v2.0/extensions.json HTTP/1.1" 200 7506 0.007402

Glance 将 volume 和 instance 绑定（130-132 行）：

2017-06-22 13:41:51.864 3958 INFO cinder.volume.manager [req-fb004f05-c2f1-4862-a848-93f5a0f9dc07 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Initialize volume connection completed successfully.
2017-06-22 13:41:52.791 3958 INFO cinder.volume.manager [req-407c52db-4234-4a9d-83ac-d6e2896503ac 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Attaching volume 4e248f95-5d7a-4a9d-9675-780acfc5246d to instance f9cc7dc5-949e-467e-b1c5-6453d6e0c47f at mountpoint /dev/vda on host None.
2017-06-22 13:41:53.586 3958 INFO cinder.volume.manager [req-407c52db-4234-4a9d-83ac-d6e2896503ac 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - default default] Attach volume completed successfully.

Nova 开始创建和启动 instance（136 行）：

2017-06-22 13:41:54.259 3610 INFO nova.virt.libvirt.driver [req-b449349a-8bb1-4cc6-8e58-8152ddf08442 1f8b1698b91c42169437f856426fc0b1 355c595975894e7d8caa9c3af1ad3cb7 - - -] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Creating image

instance 实例完成（166 行）：

2017-06-22 13:42:05.210 3610 INFO nova.virt.libvirt.driver [-] [instance: f9cc7dc5-949e-467e-b1c5-6453d6e0c47f] Instance spawned successfully.