O054、Attach Volume 操作（Part II）
参考https://www.cnblogs.com/CloudMan6/p/5631328.html
计算节点作为iSCSI initiator 访问存储节点 iSCSI Target 上的volume，并将其attach 到 Instance 。
nova-compute 一次执行 iscsiadmin 的 new、update、login、rescan 操作访问target 上的volume
计算节点将iSCSI target 上的volume识别为一个磁盘文件
然后通过更新Instance的XML配置文件将volume 映射给Instance
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@n-api.service: DEBUG nova.api.openstack.wsgi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Action: 'create', calling method: <bound method VolumeAttachmentController.create of <nova.api.openstack.compute.volumes.VolumeAttachmentController object at 0x7f9789b1cf90>>, body: {"volumeAttachment": {"volumeId": "fe3d0886-6dfb-4cc6-898a-72e902fba912"}} {{(pid=3631) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:615}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@n-api.service: DEBUG nova.compute.api [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] [instance: 502d7935-e350-4164-8ef4-95cc8b34bd54] Fetching instance by UUID {{(pid=3631) get /opt/stack/nova/nova/compute/api.py:2421}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@n-api.service: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "fe4d50b2-4e42-45ad-af8c-acb570540b3c" acquired by "nova.context.get_or_set_cached_cell_and_set_connections" :: waited 0.000s {{(pid=3631) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@n-api.service: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "fe4d50b2-4e42-45ad-af8c-acb570540b3c" released by "nova.context.get_or_set_cached_cell_and_set_connections" :: held 0.000s {{(pid=3631) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-36721fe0-2996-4610-9870-a00d7470d4d6 admin admin] GET http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/volumes/fe3d0886-6dfb-4cc6-898a-72e902fba912
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-36721fe0-2996-4610-9870-a00d7470d4d6 admin admin] Empty body provided in request {{(pid=21071) get_body /opt/stack/cinder/cinder/api/openstack/wsgi.py:718}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-36721fe0-2996-4610-9870-a00d7470d4d6 admin admin] Calling method 'show' {{(pid=21071) _process_stack /opt/stack/cinder/cinder/api/openstack/wsgi.py:872}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.volume.api [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-36721fe0-2996-4610-9870-a00d7470d4d6 admin admin] Volume info retrieved successfully.
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-36721fe0-2996-4610-9870-a00d7470d4d6 admin admin] http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/volumes/fe3d0886-6dfb-4cc6-898a-72e902fba912 returned with HTTP 200
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-7092d57a-092b-41db-a2ae-f5da4696bf10 admin admin] POST http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-7092d57a-092b-41db-a2ae-f5da4696bf10 admin admin] Action: 'create', calling method: version_select, body: {"attachment": {"instance_uuid": "502d7935-e350-4164-8ef4-95cc8b34bd54", "connector": null, "volume_uuid": "fe3d0886-6dfb-4cc6-898a-72e902fba912"}} {{(pid=21071) _process_stack /opt/stack/cinder/cinder/api/openstack/wsgi.py:869}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-7092d57a-092b-41db-a2ae-f5da4696bf10 admin admin] http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments returned with HTTP 200
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@n-api.service: INFO nova.api.openstack.requestlog [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] 10.12.30.21 "POST /compute/v2.1/servers/502d7935-e350-4164-8ef4-95cc8b34bd54/os-volume_attachments" status: 200 len: 194 microversion: 2.1 time: 0.485424
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-3f7c443e-3727-4c88-abd7-996aa93c00c6 admin admin] GET http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/volumes/fe3d0886-6dfb-4cc6-898a-72e902fba912
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-3f7c443e-3727-4c88-abd7-996aa93c00c6 admin admin] Empty body provided in request {{(pid=21070) get_body /opt/stack/cinder/cinder/api/openstack/wsgi.py:718}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-3f7c443e-3727-4c88-abd7-996aa93c00c6 admin admin] Calling method 'show' {{(pid=21070) _process_stack /opt/stack/cinder/cinder/api/openstack/wsgi.py:872}}
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.volume.api [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-3f7c443e-3727-4c88-abd7-996aa93c00c6 admin admin] Volume info retrieved successfully.
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-3f7c443e-3727-4c88-abd7-996aa93c00c6 admin admin] http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/volumes/fe3d0886-6dfb-4cc6-898a-72e902fba912 returned with HTTP 200
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin admin] PUT http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments/f742381a-9b3d-41a3-9513-5dd80e2ce6c2
Jul 1 20:50:15 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin admin] Action: 'update', calling method: version_select, body: {"attachment": {"connector": {"initiator": "iqn.1994-05.com.redhat:d77c331f2be5", "ip": "10.12.30.22", "platform": "x86_64", "host": "DevStack-Rocky-Compute-22", "do_local_attach": false, "mountpoint": "/dev/vdb", "os_type": "linux2", "multipath": false}}} {{(pid=21070) _process_stack /opt/stack/cinder/cinder/api/openstack/wsgi.py:869}}
Jul 1 20:50:19 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin admin] http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments/f742381a-9b3d-41a3-9513-5dd80e2ce6c2 returned with HTTP 200
Jul 1 20:50:20 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-2822f736-68ea-49f8-bfde-363aff42b6ec admin admin] POST http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments/f742381a-9b3d-41a3-9513-5dd80e2ce6c2/action
Jul 1 20:50:20 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-2822f736-68ea-49f8-bfde-363aff42b6ec admin admin] Action body: {"os-complete": null} {{(pid=21071) get_method /opt/stack/cinder/cinder/api/openstack/wsgi.py:986}}
Jul 1 20:50:20 DevStack-Rocky-Controller-21 devstack@c-api.service: DEBUG cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-2822f736-68ea-49f8-bfde-363aff42b6ec admin admin] Action: 'action', calling method: version_select, body: {"os-complete": null} {{(pid=21071) _process_stack /opt/stack/cinder/cinder/api/openstack/wsgi.py:869}}
Jul 1 20:50:20 DevStack-Rocky-Controller-21 devstack@c-api.service: INFO cinder.api.openstack.wsgi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-2822f736-68ea-49f8-bfde-363aff42b6ec admin admin] http://10.12.30.21/volume/v3/9ed27f1df9814f91b370d1003b066b0a/attachments/f742381a-9b3d-41a3-9513-5dd80e2ce6c2/action returned with HTTP 204
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "502d7935-e350-4164-8ef4-95cc8b34bd54" acquired by "nova.compute.manager.do_reserve" :: waited 0.000s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.objects.instance [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lazy-loading 'flavor' on Instance uuid 502d7935-e350-4164-8ef4-95cc8b34bd54 {{(pid=25886) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1111}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "502d7935-e350-4164-8ef4-95cc8b34bd54" released by "nova.compute.manager.do_reserve" :: held 0.106s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "502d7935-e350-4164-8ef4-95cc8b34bd54" acquired by "nova.compute.manager.do_attach_volume" :: waited 0.000s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: INFO nova.compute.manager [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] [instance: 502d7935-e350-4164-8ef4-95cc8b34bd54] Attaching volume fe3d0886-6dfb-4cc6-898a-72e902fba912 to /dev/vdb
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.objects.instance [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lazy-loading 'flavor' on Instance uuid 502d7935-e350-4164-8ef4-95cc8b34bd54 {{(pid=25886) obj_load_attr /opt/stack/nova/nova/objects/instance.py:1111}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.utils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] ==> get_connector_properties: call u"{'execute': None, 'my_ip': '10.12.30.22', 'enforce_multipath': True, 'host': 'DevStack-Rocky-Compute-22', 'root_helper': 'sudo nova-rootwrap /etc/nova/rootwrap.conf', 'multipath': False}" {{(pid=25886) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:146}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.linuxfc [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] No Fibre Channel support detected on system. {{(pid=25886) get_fc_hbas /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:134}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.linuxfc [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] No Fibre Channel support detected on system. {{(pid=25886) get_fc_hbas /usr/lib/python2.7/site-packages/os_brick/initiator/linuxfc.py:134}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.utils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] <== get_connector_properties: return (8ms) {'initiator': u'iqn.1994-05.com.redhat:d77c331f2be5', 'ip': u'10.12.30.22', 'platform': u'x86_64', 'host': u'DevStack-Rocky-Compute-22', 'do_local_attach': False, 'os_type': u'linux2', 'multipath': False} {{(pid=25886) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:170}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.block_device [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] [instance: 502d7935-e350-4164-8ef4-95cc8b34bd54] Updating existing volume attachment record: f742381a-9b3d-41a3-9513-5dd80e2ce6c2 {{(pid=25886) _volume_attach /opt/stack/nova/nova/virt/block_device.py:535}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvchange -a y --yes -K stack-volumes-lvmdriver-1/volume-fe3d0886-6dfb-4cc6-898a-72e902fba912" returned: 0 in 0.287s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 cinder-volume: INFO cinder.volume.targets.lio [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Creating iscsi_target for volume: volume-fe3d0886-6dfb-4cc6-898a-72e902fba912
Jul 1 20:50:15 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" acquired by "cinder.volume.targets.lio._execute" :: waited 0.001s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:15 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool create /dev/stack-volumes-lvmdriver-1/volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 6r6g96v5d9z6kCzCRaMr uKSpojdTH2ajUz9d False -p3260 -a10.12.30.22 {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:16 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool create /dev/stack-volumes-lvmdriver-1/volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 6r6g96v5d9z6kCzCRaMr uKSpojdTH2ajUz9d False -p3260 -a10.12.30.22" returned: 0 in 0.864s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:16 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" released by "cinder.volume.targets.lio._execute" :: held 0.866s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:16 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" acquired by "cinder.volume.targets.lio._execute" :: waited 0.000s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:16 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool get-targets {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool get-targets" returned: 0 in 0.472s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" released by "cinder.volume.targets.lio._execute" :: held 0.474s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" acquired by "cinder.volume.targets.lio._execute" :: waited 0.000s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool save {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool save" returned: 0 in 0.500s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" released by "cinder.volume.targets.lio._execute" :: held 0.503s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG cinder.volume.targets.iscsi [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Set provider_location to: 10.12.30.22:3260,iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 0 {{(pid=27933) create_export /opt/stack/cinder/cinder/volume/targets/iscsi.py:215}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" acquired by "cinder.volume.targets.lio._execute" :: waited 0.000s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:17 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool add-initiator iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 6r6g96v5d9z6kCzCRaMr uKSpojdTH2ajUz9d iqn.1994-05.com.redhat:d77c331f2be5 {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool add-initiator iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912 6r6g96v5d9z6kCzCRaMr uKSpojdTH2ajUz9d iqn.1994-05.com.redhat:d77c331f2be5" returned: 0 in 0.464s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" released by "cinder.volume.targets.lio._execute" :: held 0.466s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" acquired by "cinder.volume.targets.lio._execute" :: waited 0.000s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool save {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:372}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.processutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] CMD "sudo cinder-rootwrap /etc/cinder/rootwrap.conf cinder-rtstool save" returned: 0 in 0.487s {{(pid=27933) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:409}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: DEBUG oslo_concurrency.lockutils [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] Lock "lioadm" released by "cinder.volume.targets.lio._execute" :: held 0.489s {{(pid=27933) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 cinder-volume: INFO cinder.volume.manager [req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a req-b78805cd-823e-4ce5-b708-f37efd6ac60c admin None] attachment_update completed successfully.
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.volume.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Calling os-brick to attach iSCSI Volume {{(pid=25886) connect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:63}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] ==> connect_volume: call u"{'args': (<os_brick.initiator.connectors.iscsi.ISCSIConnector object at 0x7f8084f8c810>, {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-fe3d0886-6dfb-4cc6-898a-72e902fba912', u'target_portal': u'10.12.30.22:3260', u'volume_id': u'fe3d0886-6dfb-4cc6-898a-72e902fba912', u'target_lun': 0, u'auth_password': u'***', u'auth_username': u'6r6g96v5d9z6kCzCRaMr', u'auth_method': u'CHAP'}), 'kwargs': {}}" {{(pid=25886) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:146}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "connect_volume" acquired by "os_brick.initiator.connectors.iscsi.connect_volume" :: waited 0.000s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:273}}
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: INFO os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Trying to connect to iSCSI portal 10.12.30.22:3260
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm (): stdout= stderr=iscsiadm: No records found
Jul 1 20:50:18 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--interface', 'default', '--op', 'new'): stdout=New iSCSI node [tcp:[hw=,ip=,net_if=,iscsi_if=default] 10.12.30.22,3260,-1 iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912] added
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.scan', '-v', 'manual'): stdout= stderr= {{(pid=25886) _run_iscsiadm /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:973}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.authmethod', '-v', u'CHAP'): stdout= stderr= {{(pid=25886) _run_iscsiadm /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:973}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.username', '-v', u'6r6g96v5d9z6kCzCRaMr'): stdout= stderr= {{(pid=25886) _run_iscsiadm /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:973}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--op', 'update', '-n', 'node.session.auth.password', '-v', u'***'): stdout= stderr= {{(pid=25886) _run_iscsiadm /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:973}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('-m', 'session'): stdout=tcp: [1] 10.12.30.21:3260,1 iqn.2010-10.org.openstack:volume-06984f3c-44e1-42a5-b03c-08a0cfa19f73 (non-flash)
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsi session list stdout=tcp: [1] 10.12.30.21:3260,1 iqn.2010-10.org.openstack:volume-06984f3c-44e1-42a5-b03c-08a0cfa19f73 (non-flash)
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--login',): stdout=Logging in to [iface: default, target: iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912, portal: 10.12.30.22,3260] (multiple)
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('--op', 'update', '-n', 'node.startup', '-v', 'automatic'): stdout= stderr= {{(pid=25886) _run_iscsiadm /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:973}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsiadm ('-m', 'session'): stdout=tcp: [1] 10.12.30.21:3260,1 iqn.2010-10.org.openstack:volume-06984f3c-44e1-42a5-b03c-08a0cfa19f73 (non-flash)
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] iscsi session list stdout=tcp: [1] 10.12.30.21:3260,1 iqn.2010-10.org.openstack:volume-06984f3c-44e1-42a5-b03c-08a0cfa19f73 (non-flash)
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Connected to 10.12.30.22:3260 {{(pid=25886) _connect_vol /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:624}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.linuxscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] HCTL (u'4', '-', '-', 0) found on session 2 with lun 0 {{(pid=25886) get_hctl /usr/lib/python2.7/site-packages/os_brick/initiator/linuxscsi.py:622}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.linuxscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Scanning host 4 c: -, t: -, l: 0) {{(pid=25886) scan_iscsi /usr/lib/python2.7/site-packages/os_brick/initiator/linuxscsi.py:650}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.linuxscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Searching for a device in session 2 and hctl [u'4', '*', '*', 0] yield: sdc {{(pid=25886) device_name_by_hctl /usr/lib/python2.7/site-packages/os_brick/initiator/linuxscsi.py:642}}
Jul 1 20:50:19 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Connected to sdc using {u'auth_password': u'***', u'target_discovered': False, u'encrypted': False, u'qos_specs': None, u'target_iqn': u'iqn.2010-10.org.openstack:volume-fe3d0886-6dfb-4cc6-898a-72e902fba912', u'target_portal': u'10.12.30.22:3260', u'volume_id': u'fe3d0886-6dfb-4cc6-898a-72e902fba912', u'target_lun': 0, u'access_mode': u'rw', u'auth_username': u'6r6g96v5d9z6kCzCRaMr', u'auth_method': u'CHAP'} {{(pid=25886) _connect_vol /usr/lib/python2.7/site-packages/os_brick/initiator/connectors/iscsi.py:651}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "connect_volume" released by "os_brick.initiator.connectors.iscsi.connect_volume" :: held 1.148s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG os_brick.initiator.connectors.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] <== connect_volume: return (1148ms) {'path': u'/dev/sdc', 'scsi_wwn': u'3600140501eebd8031364e63a796e9a92', 'type': u'block'} {{(pid=25886) trace_logging_wrapper /usr/lib/python2.7/site-packages/os_brick/utils.py:170}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.volume.iscsi [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Attached iSCSI volume {'path': u'/dev/sdc', 'scsi_wwn': '3600140501eebd8031364e63a796e9a92', 'type': 'block'} {{(pid=25886) connect_volume /opt/stack/nova/nova/virt/libvirt/volume/iscsi.py:65}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.guest [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] attach device xml: <disk type="block" device="disk">
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.driver [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] No BDM found with device name vda, not building metadata. {{(pid=25886) _build_disk_metadata /opt/stack/nova/nova/virt/libvirt/driver.py:8721}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.driver [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] No BDM found with device name vdb, not building metadata. {{(pid=25886) _build_disk_metadata /opt/stack/nova/nova/virt/libvirt/driver.py:8721}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG nova.virt.libvirt.driver [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] No VIF found with MAC fa:16:3e:fb:35:7a, not building metadata {{(pid=25886) _build_interface_metadata /opt/stack/nova/nova/virt/libvirt/driver.py:8697}}
Jul 1 20:50:20 DevStack-Rocky-Compute-22 nova-compute: DEBUG oslo_concurrency.lockutils [None req-d82c0c2b-7534-4ff2-b905-a25b7c2a194a admin admin] Lock "502d7935-e350-4164-8ef4-95cc8b34bd54" released by "nova.compute.manager.do_attach_volume" :: held 5.109s {{(pid=25886) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285}}