O033、Terminate Instance 操作详解
本节通过日志详细分析 Nova Terminate 操作。Terminate 操作就是删除 instance ，下面是 Terminate instance 的流程图。
① 用户向 nova-api 发送删除请求
② nova-api 向 Messaging 发送一个删除的消息
2019-05-24 13:36:10.303 DEBUG nova.api.openstack.wsgi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7fb2f89b4fd0>>' from (pid=28283) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:626
2019-05-24 13:36:10.304 DEBUG nova.compute.api [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Fetching instance by UUID from (pid=28283) get /opt/stack/nova/nova/compute/api.py:2397
2019-05-24 13:36:10.310 DEBUG oslo_concurrency.lockutils [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Lock "5fd8cdfc-e20e-46da-8c1a-88e1c5ce2790" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s from (pid=28283) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2019-05-24 13:36:10.311 DEBUG oslo_concurrency.lockutils [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Lock "5fd8cdfc-e20e-46da-8c1a-88e1c5ce2790" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.000s from (pid=28283) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2019-05-24 13:36:10.361 DEBUG nova.compute.api [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Going to try to terminate instance from (pid=28283) delete /opt/stack/nova/nova/compute/api.py:2241
2019-05-24 13:36:10.443 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Attempting to reserve resources for project c2b9e5f4a15d43218f3fca6e13c49a3a and user c23652fbcaa74c1e8becc960e2210820. Deltas: {'instances': -1, 'ram': -256, 'cores': -1} from (pid=28283) reserve /opt/stack/nova/nova/quota.py:510
2019-05-24 13:36:10.449 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Quota limits for project c2b9e5f4a15d43218f3fca6e13c49a3a: {'project_id': u'c2b9e5f4a15d43218f3fca6e13c49a3a'} from (pid=28283) reserve /opt/stack/nova/nova/quota.py:519
2019-05-24 13:36:10.449 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Getting quotas for project c2b9e5f4a15d43218f3fca6e13c49a3a. Resources: ['instances', 'ram', 'cores'] from (pid=28283) _get_quotas /opt/stack/nova/nova/quota.py:369
2019-05-24 13:36:10.453 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Quotas for project c2b9e5f4a15d43218f3fca6e13c49a3a after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} from (pid=28283) reserve /opt/stack/nova/nova/quota.py:525
2019-05-24 13:36:10.454 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Getting quotas for user c23652fbcaa74c1e8becc960e2210820 and project c2b9e5f4a15d43218f3fca6e13c49a3a. Resources: ['instances', 'ram', 'cores'] from (pid=28283) _get_quotas /opt/stack/nova/nova/quota.py:361
2019-05-24 13:36:10.460 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Quotas for project c2b9e5f4a15d43218f3fca6e13c49a3a and user c23652fbcaa74c1e8becc960e2210820 after resource sync: {'instances': 10, 'ram': 51200, 'cores': 20} from (pid=28283) reserve /opt/stack/nova/nova/quota.py:533
2019-05-24 13:36:10.502 DEBUG nova.quota [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Created reservations ['0c8c3ffd-baf5-406f-b139-7c757699798c', '575bf45e-13c6-4554-a9b8-d897bd633556', '1f3d8717-02d6-42d2-a8a0-50cb37031851'] from (pid=28283) reserve /opt/stack/nova/nova/quota.py:1383
2019-05-24 13:36:10.534 DEBUG oslo_messaging._drivers.amqpdriver [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] CAST unique_id: d85196e440914681afa4c63cd41baa9c exchange 'nova' topic 'compute.DevStack-Controller' from (pid=28283) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:550
2019-05-24 13:36:10.536 INFO nova.osapi_compute.wsgi.server [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] 10.12.31.241 "DELETE /v2.1/servers/a0e2b485-f40c-43e4-beb6-049b6399f0ec HTTP/1.1" status: 204 len: 339 time: 0.2694528
③ Nova-Compute 从Messaging获取删除消息后，执行删除操作
root@DevStack-Controller:/opt/stack/logs# cat n-cpu.log | grep req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d | grep -v oslo
2019-05-24 13:36:10.586 INFO nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Terminating instance
2019-05-24 13:36:10.592 DEBUG nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Start destroying the instance on the hypervisor. from (pid=4613) _shutdown_instance /opt/stack/nova/nova/compute/manager.py:2257
2019-05-24 13:36:11.584 DEBUG nova.virt.libvirt.vif [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d 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=<?>,disable_terminate=False,display_description='admin-test03',display_name='admin-test03',ec2_ids=<?>,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=<?>,launch_index=0,launched_at=2019-05-23T08:35:24Z,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=<?>,power_state=1,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',owner_project_name='admin',owner_user_name='admin'},tags=<?>,task_state='deleting',terminated_at=None,updated_at=2019-05-23T15:29:29Z,user_data=None,user_id='c23652fbcaa74c1e8becc960e2210820',uuid=a0e2b485-f40c-43e4-beb6-049b6399f0ec,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') 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": true, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null} from (pid=4613) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:966
2019-05-24 13:36:11.585 DEBUG nova.network.os_vif_util [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Converting 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": true, "type": "bridge", "id": "ef41d30d-862f-4342-919a-95ed7a0587e3", "qbg_params": null} from (pid=4613) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:439
2019-05-24 13:36:11.587 DEBUG nova.network.os_vif_util [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Converted object VIFBridge(active=True,address=fa:16:3e:7c:d6:21,bridge_name='brq32740d6a-81',has_traffic_filtering=True,id=ef41d30d-862f-4342-919a-95ed7a0587e3,network=Network(32740d6a-8119-4c8e-9828-fe5da5b6e7ac),plugin='linux_bridge',port_profile=<?>,preserve_on_delete=False,vif_name='tapef41d30d-86') from (pid=4613) nova_to_osvif_vif /opt/stack/nova/nova/network/os_vif_util.py:451
2019-05-24 13:36:11.588 DEBUG os_vif [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Unplugging vif VIFBridge(active=True,address=fa:16:3e:7c:d6:21,bridge_name='brq32740d6a-81',has_traffic_filtering=True,id=ef41d30d-862f-4342-919a-95ed7a0587e3,network=Network(32740d6a-8119-4c8e-9828-fe5da5b6e7ac),plugin='linux_bridge',port_profile=<?>,preserve_on_delete=False,vif_name='tapef41d30d-86') from (pid=4613) unplug /usr/local/lib/python2.7/dist-packages/os_vif/__init__.py:112
2019-05-24 13:36:11.589 INFO os_vif [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Successfully unplugged vif VIFBridge(active=True,address=fa:16:3e:7c:d6:21,bridge_name='brq32740d6a-81',has_traffic_filtering=True,id=ef41d30d-862f-4342-919a-95ed7a0587e3,network=Network(32740d6a-8119-4c8e-9828-fe5da5b6e7ac),plugin='linux_bridge',port_profile=<?>,preserve_on_delete=False,vif_name='tapef41d30d-86')
2019-05-24 13:36:11.590 DEBUG nova.virt.libvirt.volume.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] calling os-brick to detach iSCSI Volume from (pid=4613) disconnect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:72
2019-05-24 13:36:11.591 DEBUG os_brick.initiator.connectors.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] ==> disconnect_volume: call u"{'args': (<os_brick.initiator.connectors.iscsi.ISCSIConnector object at 0x7fb95a4af250>, {u'device_path': u'/dev/disk/by-path/ip-10.12.31.241:3260-iscsi-iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1-lun-1', 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'auth_password': u'***', u'target_lun': 1, u'access_mode': u'rw', u'auth_username': u'Nto8maSrg6QoWcwQ6bQ7', u'auth_method': u'CHAP'}, None), 'kwargs': {}}" from (pid=4613) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:146
2019-05-24 13:36:11.592 DEBUG os_brick.initiator.linuxscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Flushing IO for device /dev/sdd from (pid=4613) flush_device_io /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxscsi.py:146
2019-05-24 13:36:11.596 DEBUG os_brick.initiator.linuxscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Remove SCSI device /dev/sdd with /sys/block/sdd/device/delete from (pid=4613) remove_scsi_device /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxscsi.py:69
2019-05-24 13:36:11.646 DEBUG os_brick.initiator.linuxscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Checking to see if SCSI volume /dev/disk/by-path/ip-10.12.31.241:3260-iscsi-iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1-lun-1 has been removed. from (pid=4613) wait_for_volume_removal /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxscsi.py:77
2019-05-24 13:36:11.646 DEBUG os_brick.initiator.linuxscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] SCSI volume /dev/disk/by-path/ip-10.12.31.241:3260-iscsi-iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1-lun-1 has been removed. from (pid=4613) wait_for_volume_removal /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxscsi.py:83
2019-05-24 13:36:11.656 DEBUG os_brick.initiator.connectors.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] iscsiadm ('--op', 'update', '-n', 'node.startup', '-v', 'manual'): stdout= stderr= from (pid=4613) _run_iscsiadm /usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py:598
2019-05-24 13:36:12.168 DEBUG os_brick.initiator.connectors.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] iscsiadm ('--logout',): stdout=Logging out of session [sid: 5, target: iqn.2010-10.org.openstack:volume-2ba40932-cabc-40b1-9011-87354ac29fc1, portal: 10.12.31.241,3260]
2019-05-24 13:36:12.178 DEBUG os_brick.initiator.connectors.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] iscsiadm ('--op', 'delete'): stdout= stderr= from (pid=4613) _run_iscsiadm /usr/local/lib/python2.7/dist-packages/os_brick/initiator/connectors/iscsi.py:598
2019-05-24 13:36:12.178 DEBUG os_brick.initiator.connectors.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] <== disconnect_volume: return (586ms) None from (pid=4613) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:170
2019-05-24 13:36:12.178 DEBUG nova.virt.libvirt.volume.iscsi [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Disconnected iSCSI Volume vda from (pid=4613) disconnect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:78
2019-05-24 13:36:12.186 INFO nova.virt.libvirt.driver [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Deleting instance files /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec_del
2019-05-24 13:36:12.188 INFO nova.virt.libvirt.driver [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Deletion of /opt/stack/data/nova/instances/a0e2b485-f40c-43e4-beb6-049b6399f0ec_del complete
2019-05-24 13:36:12.285 INFO nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Took 1.69 seconds to destroy the instance on the hypervisor.
2019-05-24 13:36:12.286 DEBUG nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Deallocating network for instance from (pid=4613) _deallocate_network /opt/stack/nova/nova/compute/manager.py:1676
2019-05-24 13:36:12.286 DEBUG nova.network.neutronv2.api [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] deallocate_for_instance() from (pid=4613) deallocate_for_instance /opt/stack/nova/nova/network/neutronv2/api.py:1173
2019-05-24 13:36:12.368 DEBUG neutronclient.v2_0.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] GET call to neutron for http://10.12.31.241:9696/v2.0/ports.json?device_id=a0e2b485-f40c-43e4-beb6-049b6399f0ec used request id req-d980c157-2599-4c7c-9472-509f2d6a9cfc from (pid=4613) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2019-05-24 13:36:12.408 DEBUG neutronclient.v2_0.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] GET call to neutron for http://10.12.31.241:9696/v2.0/extensions.json used request id req-d3bfbdc7-88a6-4510-8651-05851fa9eee2 from (pid=4613) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2019-05-24 13:36:13.315 DEBUG neutronclient.v2_0.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] DELETE call to neutron for http://10.12.31.241:9696/v2.0/ports/ef41d30d-862f-4342-919a-95ed7a0587e3.json used request id req-df7aff17-b4ec-4f0f-9412-0f3ce0a7b40a from (pid=4613) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2019-05-24 13:36:13.335 DEBUG nova.network.base_api [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Updating instance_info_cache with network_info: [] from (pid=4613) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:48
2019-05-24 13:36:13.356 INFO nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Took 1.07 seconds to deallocate network for instance.
2019-05-24 13:36:13.357 DEBUG os_brick.utils [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] ==> get_connector_properties: call u"{'execute': None, 'my_ip': '10.12.31.241', 'enforce_multipath': True, 'host': 'DevStack-Controller', 'root_helper': 'sudo nova-rootwrap /etc/nova/rootwrap.conf', 'multipath': False}" from (pid=4613) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:146
2019-05-24 13:36:13.363 DEBUG os_brick.initiator.linuxfc [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] No Fibre Channel support detected on system. from (pid=4613) get_fc_hbas /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxfc.py:91
2019-05-24 13:36:13.363 DEBUG os_brick.initiator.linuxfc [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] No Fibre Channel support detected on system. from (pid=4613) get_fc_hbas /usr/local/lib/python2.7/dist-packages/os_brick/initiator/linuxfc.py:91
2019-05-24 13:36:13.364 DEBUG os_brick.utils [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] <== get_connector_properties: return (6ms) {'initiator': u'iqn.1993-08.org.debian:01:1997f5bacda', 'ip': u'10.12.31.241', 'platform': u'x86_64', 'host': u'DevStack-Controller', 'do_local_attach': False, 'os_type': u'linux2', 'multipath': False} from (pid=4613) trace_logging_wrapper /usr/local/lib/python2.7/dist-packages/os_brick/utils.py:170
2019-05-24 13:36:13.366 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d 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}dd87832868296fc2816e893da621c1b51eb51a45" -d '{"os-terminate_connection": {"connector": {"platform": "x86_64", "host": "DevStack-Controller", "do_local_attach": false, "ip": "10.12.31.241", "os_type": "linux2", "multipath": false, "initiator": "iqn.1993-08.org.debian:01:1997f5bacda"}}}' from (pid=4613) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:347
2019-05-24 13:36:13.666 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] RESP: [202] Content-Type: text/html; charset=UTF-8 Content-Length: 0 X-Openstack-Request-Id: req-43c5a9bf-4fa2-4cfa-bd98-31c71ce03b35 Date: Fri, 24 May 2019 05:36:13 GMT Connection: keep-alive
2019-05-24 13:36:13.667 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] POST call to cinderv2 for http://10.12.31.241:8776/v2/c2b9e5f4a15d43218f3fca6e13c49a3a/volumes/2ba40932-cabc-40b1-9011-87354ac29fc1/action used request id req-43c5a9bf-4fa2-4cfa-bd98-31c71ce03b35 from (pid=4613) request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:640
2019-05-24 13:36:13.669 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] REQ: curl -g -i -X GET http://10.12.31.241:8776/v2/c2b9e5f4a15d43218f3fca6e13c49a3a/volumes/2ba40932-cabc-40b1-9011-87354ac29fc1 -H "User-Agent: python-cinderclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dd87832868296fc2816e893da621c1b51eb51a45" from (pid=4613) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:347
2019-05-24 13:36:13.771 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] RESP: [200] X-Compute-Request-Id: req-ea542543-5db3-43eb-b32e-c974eec79d6f Content-Type: application/json Content-Length: 1730 X-Openstack-Request-Id: req-ea542543-5db3-43eb-b32e-c974eec79d6f Date: Fri, 24 May 2019 05:36:13 GMT Connection: keep-alive
2019-05-24 13:36:13.772 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] GET call to cinderv2 for http://10.12.31.241:8776/v2/c2b9e5f4a15d43218f3fca6e13c49a3a/volumes/2ba40932-cabc-40b1-9011-87354ac29fc1 used request id req-ea542543-5db3-43eb-b32e-c974eec79d6f from (pid=4613) request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:640
2019-05-24 13:36:13.772 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d 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}dd87832868296fc2816e893da621c1b51eb51a45" -d '{"os-detach": {"attachment_id": null}}' from (pid=4613) _http_log_request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:347
2019-05-24 13:36:14.964 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] RESP: [202] Content-Type: text/html; charset=UTF-8 Content-Length: 0 X-Openstack-Request-Id: req-feb9e33d-5fb6-484e-acbb-bd4bb4a221ba Date: Fri, 24 May 2019 05:36:14 GMT Connection: keep-alive
2019-05-24 13:36:14.964 DEBUG cinderclient.v2.client [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] POST call to cinderv2 for http://10.12.31.241:8776/v2/c2b9e5f4a15d43218f3fca6e13c49a3a/volumes/2ba40932-cabc-40b1-9011-87354ac29fc1/action used request id req-feb9e33d-5fb6-484e-acbb-bd4bb4a221ba from (pid=4613) request /usr/local/lib/python2.7/dist-packages/keystoneauth1/session.py:640
2019-05-24 13:36:14.965 INFO nova.compute.manager [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] [instance: a0e2b485-f40c-43e4-beb6-049b6399f0ec] Took 1.61 seconds to detach 1 volumes for instance.
2019-05-24 13:36:15.293 INFO nova.scheduler.client.report [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Deleted allocation for instance a0e2b485-f40c-43e4-beb6-049b6399f0ec
2019-05-24 13:36:15.337 DEBUG nova.scheduler.client.report [req-14f2b96d-8a6d-45ed-bb0c-d59ee14e3b2d admin admin] Refreshing aggregate associations for resource provider 3ead96c5-1460-4573-8154-15b6727c1178 from (pid=4613) _ensure_resource_provider /opt/stack/nova/nova/scheduler/client/report.py:402
