Hide Forgot
Created attachment 1429990 [details] Logs Description of problem: When I try to attach an encrypted volume created from an image, where image was another encrypted volume, volume fails to attach. Nova compute logs reports errors attached, also added other logs Cinder/Nova/Barbican. Now this might be a case of how the source image was created, meaning encryption once on source volume, then when I created a new volume form this uploaded image when I specified --volume-type LUKS which probably added a second layer of encryption, which might have caused this whole (possibly not-a)bug. But then again shouldn't volume attach still work, OK I won't see my original data but that's something else. Version-Release number of selected component (if applicable): rhel 7.5 openstack-nova-common-17.0.3-0.20180420001138.el7ost.noarch openstack-nova-api-17.0.3-0.20180420001138.el7ost.noarch puppet-nova-12.4.0-2.el7ost.noarch openstack-nova-conductor-17.0.3-0.20180420001138.el7ost.noarch openstack-nova-novncproxy-17.0.3-0.20180420001138.el7ost.noarch python-novaclient-9.1.1-1.el7ost.noarch openstack-nova-compute-17.0.3-0.20180420001138.el7ost.noarch python-nova-17.0.3-0.20180420001138.el7ost.noarch python-cinder-12.0.1-0.20180418194613.c476898.el7ost.noarch puppet-cinder-12.4.1-0.20180329071637.4011a82.el7ost.noarch openstack-cinder-12.0.1-0.20180418194613.c476898.el7ost.noarch How reproducible: Every time Steps to Reproduce: 1. Create an encrypted Cinder volume cinder create 1 --volume-type LUKS 2. Attach to an instance mkfs.ext4 mount and save a file to volume nova volume-attach 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea 23ce20c9-fa03-4638-ae6e-452cffb884fa auto 3. Detach volume nova volume-detach 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea 23ce20c9-fa03-4638-ae6e-452cffb884fa 4. Upload to Glance openstack image create --disk-format raw --container-format bare --volume 23ce20c9-fa03-4638-ae6e-452cffb884fa EncVolPlusData 5. Create a new encrypted volume from image cinder create 2 --image d97b4bf7-e031-43d6-9e8f-3df25ea9c3f1 --volume-type LUKS 6. Try to attach volume - fails volume says attaching later returns to available. nova volume-attach 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea a23f5c23-1dbc-413e-afac-e2b6285d0aa6 auto Actual results: Volume remains unattached From nova compute log: mpute-request-id: req-48651fb6-f9e8-4754-8993-d9d0f6d84fe1 x-openstack-request-id: req-48651fb6-f9e8-4754-8993-d9d0f6d84fe1 Content-Length: 149 Content-Type: application/json RESP BODY: {"itemNotFound": {"message": "Volume attachment could not be found with filter: attachment_id = af9c165b-8612-4969-a6e0-4ef119025a78.", "code": 404}} _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:419 2018-05-02 11:25:10.091 1 DEBUG cinderclient.v3.client [req-ceafede1-ec7e-494e-ab0e-830622e64288 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] DELETE call to cinderv3 for http://172.17.1.19:8776/v3/4e0b66c6ff994c8f8e306cca69781c87/attachments/af9c165b-8612-4969-a6e0-4ef119025a78 used request id req-48651fb6-f9e8-4754-8993-d9d0f6d84fe1 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:722 2018-05-02 11:25:10.093 1 ERROR nova.volume.cinder [req-ceafede1-ec7e-494e-ab0e-830622e64288 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] Delete attachment failed for attachment af9c165b-8612-4969-a6e0-4ef119025a78. Error: Volume attachment could not be found with filter: attachment_id = af9c165b-8612-4969-a6e0-4ef119025a78. (HTTP 404) (Request-ID: req-48651fb6-f9e8-4754-8993-d9d0f6d84fe1) Code: 404: NotFound: Volume attachment could not be found with filter: attachment_id = af9c165b-8612-4969-a6e0-4ef119025a78. (HTTP 404) (Request-ID: req-48651fb6-f9e8-4754-8993-d9d0f6d84fe1) 2018-05-02 11:25:10.095 1 ERROR root [req-ceafede1-ec7e-494e-ab0e-830622e64288 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] Original exception being dropped: ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5303, in _attach_volume\n do_driver_attach=True)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 46, in wrapped\n ret_val = method(obj, context, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 617, in attach\n virt_driver, do_driver_attach)\n', ' File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 274, in inner\n return f(*args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 614, in _do_locked_attach\n self._do_attach(*args, **_kwargs)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 599, in _do_attach\n do_driver_attach)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 547, in _volume_attach\n attachment_id)\n', ' File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__\n self.force_reraise()\n', ' File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 538, in _volume_attach\n device_type=self[\'device_type\'], encryption=encryption)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1478, in attach_volume\n encryption=encryption)\n', ' File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__\n self.force_reraise()\n', ' File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise\n six.reraise(self.type_, self.value, self.tb)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1461, in attach_volume\n guest.attach_device(conf, persistent=True, live=live)\n', ' File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/guest.py", line 303, in attach_device\n self._domain.attachDeviceFlags(device_xml, flags=flags)\n', ' File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 186, in doit\n result = proxy_call(self._autowrap, f, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 144, in proxy_call\n rv = execute(f, *args, **kwargs)\n', ' File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 125, in execute\n six.reraise(c, e, tb)\n', ' File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 83, in tworker\n rv = meth(*args, **kwargs)\n', ' File "/usr/lib64/python2.7/site-packages/libvirt.py", line 594, in attachDeviceFlags\n if ret == -1: raise libvirtError (\'virDomainAttachDeviceFlags() failed\', dom=self)\n', "libvirtError: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized\n"]: VolumeAttachmentNotFound: Volume attachment af9c165b-8612-4969-a6e0-4ef119025a78 could not be found. 2018-05-02 11:25:10.136 1 DEBUG oslo_concurrency.lockutils [req-ceafede1-ec7e-494e-ab0e-830622e64288 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] Lock "4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea" released by "nova.compute.manager.do_attach_volume" :: held 16.317s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:285 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server [req-ceafede1-ec7e-494e-ab0e-830622e64288 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] Exception during message handling: VolumeAttachmentNotFound: Volume attachment af9c165b-8612-4969-a6e0-4ef119025a78 could not be found. 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server Traceback (most recent call last): 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/server.py", line 163, in _process_incoming 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server res = self.dispatcher.dispatch(message) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 220, in dispatch 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 190, in _do_dispatch 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server result = func(ctxt, **new_args) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 76, in wrapped 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server function_name, call_dict, binary) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server self.force_reraise() 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/exception_wrapper.py", line 67, in wrapped 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return f(self, context, *args, **kw) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/utils.py", line 976, in decorated_function 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return function(self, context, *args, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 214, in decorated_function 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server kwargs['instance'], e, sys.exc_info()) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server self.force_reraise() 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 202, in decorated_function 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return function(self, context, *args, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5288, in attach_volume 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server do_attach_volume(context, instance, driver_bdm) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 274, in inner 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return f(*args, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5286, in do_attach_volume 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server bdm.destroy() 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server self.force_reraise() 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5283, in do_attach_volume 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return self._attach_volume(context, instance, driver_bdm) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 5313, in _attach_volume 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server bdm['attachment_id']) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 379, in wrapper 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server res = method(self, ctx, *args, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 418, in wrapper 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server attachment_id=attachment_id)) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 450, in _reraise 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server six.reraise(type(desired_exc), desired_exc, sys.exc_info()[2]) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 415, in wrapper 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server res = method(self, ctx, attachment_id, *args, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 838, in attachment_delete 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server 'code': getattr(ex, 'code', None)}) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server self.force_reraise() 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server six.reraise(self.type_, self.value, self.tb) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 831, in attachment_delete 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server attachment_id) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinderclient/v3/attachments.py", line 39, in delete 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return self._delete("/attachments/%s" % base.getid(attachment)) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinderclient/base.py", line 339, in _delete 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server resp, body = self.api.client.delete(url) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 209, in delete 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return self._cs_request(url, 'DELETE', **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 191, in _cs_request 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server return self.request(url, method, **kwargs) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 177, in request 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server raise exceptions.from_response(resp, body) 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server VolumeAttachmentNotFound: Volume attachment af9c165b-8612-4969-a6e0-4ef119025a78 could not be found. 2018-05-02 11:25:10.295 1 ERROR oslo_messaging.rpc.server 2018-05-02 11:25:11.322 1 DEBUG oslo_service.periodic_task [req-cea Expected results: Volume should successfully attach to an instance. Additional info: Well I see some nova compute log related error but it might be related to Cinder encryption/Babrican or that upload to glance.
Nova compute does: 2018-05-02 11:12:18.362 [nova-compute.log] 1 DEBUG nova.virt.libvirt.host [req-97b2a5a2-170c-43f3-89cb-6588e39c4a03 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] Secret XML: <secret ephemeral="no" private="no"> <usage type="volume"> <volume>a23f5c23-1dbc-413e-afac-e2b6285d0aa6</volume> </usage> </secret> create_secret /usr/lib/python2.7/site-packages/nova/virt/libvirt/host.py:732 2018-05-02 11:12:18.389 [nova-compute.log] 1 DEBUG nova.virt.libvirt.guest [req-97b2a5a2-170c-43f3-89cb-6588e39c4a03 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] attach device xml: <disk type="network" device="disk"> <driver name="qemu" type="raw" cache="writeback" discard="unmap"/> <source protocol="rbd" name="volumes/volume-a23f5c23-1dbc-413e-afac-e2b6285d0aa6"> <host name="172.17.3.16" port="6789"/> <host name="172.17.3.18" port="6789"/> <host name="172.17.3.20" port="6789"/> </source> <auth username="openstack"> <secret type="ceph" uuid="cd20e710-4b99-11e8-bfec-525400688018"/> </auth> <target bus="virtio" dev="vdb"/> <serial>a23f5c23-1dbc-413e-afac-e2b6285d0aa6</serial> <encryption format="luks"> <secret type="passphrase" uuid="8859017b-e4b8-4387-b7cb-215db09a3730"/> </encryption> </disk> attach_device /usr/lib/python2.7/site-packages/nova/virt/libvirt/guest.py:302 which results in: 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [req-97b2a5a2-170c-43f3-89cb-6588e39c4a03 17143d85ea234df191e5b5ac06a6489f 4e0b66c6ff994c8f8e306cca69781c87 - default default] [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] Failed to attach volume at mountpoint: /dev/vdb: libvirtError: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] Traceback (most recent call last): 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 1461, in attach_volume 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] guest.attach_device(conf, persistent=True, live=live) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/guest.py", line 303, in attach_device 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] self._domain.attachDeviceFlags(device_xml, flags=flags) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 186, in doit 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] result = proxy_call(self._autowrap, f, *args, **kwargs) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 144, in proxy_call 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] rv = execute(f, *args, **kwargs) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 125, in execute 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] six.reraise(c, e, tb) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 83, in tworker 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] rv = meth(*args, **kwargs) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] File "/usr/lib64/python2.7/site-packages/libvirt.py", line 594, in attachDeviceFlags 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] if ret == -1: raise libvirtError ('virDomainAttachDeviceFlags() failed', dom=self) 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea] libvirtError: internal error: unable to execute QEMU command '__com.redhat_drive_add': Device 'drive-virtio-disk1' could not be initialized 2018-05-02 11:12:20.813 [nova-compute.log] 1 ERROR nova.virt.libvirt.driver [instance: 4dcc222e-8522-4ca3-badb-1ae9ca3bb3ea]
The logs in Comment 1 indicate that qemu can't add the disk. This may or may not be the root cause, but I'd like to start here anyway. Possible cause: bug 1406796 suggests that we don't yet support native LUKS encryption on RBD. Please could you provide libvirt debug logs as detailed here: https://kashyapc.fedorapeople.org/virt/openstack/request-nova-libvirt-qemu-debug-logs.txt Also sosreports would be preferrable to cherry-picked logs. Please could you provide sosreports from the relevant controller(s) and compute?
(In reply to Matthew Booth from comment #2) > The logs in Comment 1 indicate that qemu can't add the disk. This may or may > not be the root cause, but I'd like to start here anyway. > > Possible cause: bug 1406796 suggests that we don't yet support native LUKS > encryption on RBD. That's covering full support for all blockdev operations, something that isn't required here to simply attach and decrypt the new rbd volume. > Please could you provide libvirt debug logs as detailed here: > > https://kashyapc.fedorapeople.org/virt/openstack/request-nova-libvirt-qemu- > debug-logs.txt > > Also sosreports would be preferrable to cherry-picked logs. Please could you > provide sosreports from the relevant controller(s) and compute? Agreed, can we also get the output of the following commands from a host with the required rbd keys: $ qemu-img info volumes/volume-23ce20c9-fa03-4638-ae6e-452cffb884fa $ qemu-img info volumes/volume-a23f5c23-1dbc-413e-afac-e2b6285d0aa6 Finally, can you also try attaching the volume to another instance?
I've reproduced the issue, on a new system logs are available. Also noticed another oddity on this new system, might have happened on original system I didn't notice it back then. The new volume I create on step 5 (ID a6591d92-e838-4ab1-8644-81aba6f746c6) is listed as bootable which is false, as it only contains as a text file on it. Suspect there is another Glance/Cinder bug lurking in the shadows here. I've enabled libvirt logs now tried to attach this second new volume -> d8b360fa-6348-4d7c-9714-dfbeee88fd8d also failing, same as step5 just another volume. Versions of new system: openstack-cinder-12.0.1-0.20180418194613.c476898.el7ost.noarch openstack-nova-compute-17.0.3-0.20180420001139.el7ost.noarch openstack-glance-16.0.1-2.el7ost.noarch openstack-nova-common-17.0.3-0.20180420001139.el7ost.noarch openstack-nova-api-17.0.3-0.20180420001139.el7ost.noarch On this new system qemu-image of the three volumes qemu-img info volumes/volume-17276f8b-c21d-479e-a58a-522319d01ff8 qemu-img: Could not open 'volumes/volume-17276f8b-c21d-479e-a58a-522319d01ff8': Could not open 'volumes/volume-17276f8b-c21d-479e-a58a-522319d01ff8': No such file or directory [root@controller-0 tmp]# qemu-img info rbd:volumes/volume-17276f8b-c21d-479e-a58a-522319d01ff8 image: json:{"driver": "luks", "file": {"pool": "volumes", "image": "volume-17276f8b-c21d-479e-a58a-522319d01ff8", "driver": "rbd"}} file format: luks virtual size: 1.0G (1073741824 bytes) disk size: unavailable encrypted: yes cluster_size: 4194304 Format specific information: ivgen alg: plain64 hash alg: sha256 cipher alg: aes-256 uuid: 8d41fc3e-d134-480c-a35e-a42bf8a5763b cipher mode: xts slots: [0]: active: true iters: 1038604 key offset: 4096 stripes: 4000 [1]: active: false key offset: 262144 [2]: active: false key offset: 520192 [3]: active: false key offset: 778240 [4]: active: false key offset: 1036288 [5]: active: false key offset: 1294336 [6]: active: false key offset: 1552384 [7]: active: false key offset: 1810432 payload offset: 2068480 master key iters: 259425 qemu-img info rbd:volumes/volume-a6591d92-e838-4ab1-8644-81aba6f746c6 image: json:{"driver": "luks", "file": {"pool": "volumes", "image": "volume-a6591d92-e838-4ab1-8644-81aba6f746c6", "driver": "rbd"}} file format: luks virtual size: 2.0G (2145415168 bytes) disk size: unavailable encrypted: yes cluster_size: 4194304 Format specific information: ivgen alg: plain64 hash alg: sha256 cipher alg: aes-256 uuid: 8d41fc3e-d134-480c-a35e-a42bf8a5763b cipher mode: xts slots: [0]: active: true iters: 1038604 key offset: 4096 stripes: 4000 [1]: active: false key offset: 262144 [2]: active: false key offset: 520192 [3]: active: false key offset: 778240 [4]: active: false key offset: 1036288 [5]: active: false key offset: 1294336 [6]: active: false key offset: 1552384 [7]: active: false key offset: 1810432 payload offset: 2068480 master key iters: 259425 qemu-img info rbd:volumes/volume-d8b360fa-6348-4d7c-9714-dfbeee88fd8d image: json:{"driver": "luks", "file": {"pool": "volumes", "image": "volume-d8b360fa-6348-4d7c-9714-dfbeee88fd8d", "driver": "rbd"}} file format: luks virtual size: 2.0G (2145415168 bytes) disk size: unavailable encrypted: yes cluster_size: 4194304 Format specific information: ivgen alg: plain64 hash alg: sha256 cipher alg: aes-256 uuid: 8d41fc3e-d134-480c-a35e-a42bf8a5763b cipher mode: xts slots: [0]: active: true iters: 1038604 key offset: 4096 stripes: 4000 [1]: active: false key offset: 262144 [2]: active: false key offset: 520192 [3]: active: false key offset: 778240 [4]: active: false key offset: 1036288 [5]: active: false key offset: 1294336 [6]: active: false key offset: 1552384 [7]: active: false key offset: 1810432 payload offset: 2068480 master key iters: 259425
Thanks for the logs and access to the underlying host Tzach! I've updated the upstream bug with my findings and am moving this downstream bug across to Cinder. AFAICT Cinder is creating a fresh Barbican secret that is itself unable to unlock the original LUKS encryption on the volume. The entire flow needs to be reviewed by the Cinder team as we appear to be doing duplicate downloads of the image from Glance and conversions on the c-vol host. I assume this is where the new secret is also created. Let me know if I can help anymore with this!
One indicator of what's happening here is this message in the qemu log for the instance when the attach fails (the last line): # cat /var/log/libvirt/qemu/instance-00000002.log 'serial' is deprecated, please use the corresponding option of '-device' instead 'serial' is deprecated, please use the corresponding option of '-device' instead Invalid password, cannot unlock any keyslot
Waiting to rebuild my server as latest deployment was short of fixed-in -> openstack-cinder-12.0.1-0.20180418194613.c476898.el7ost.noarch Are we still waiting for rpm/package, as we have a fix-in but status isn't ON_QA yet.
Verified on openstack-cinder-12.0.1-0.20180418194614.c476898.el7ost Puddle date 2018-06-04.2 Create a LUKS (Barbican) volume: #cinder create 1 --volume-type LUKS - created -> | 9230d56a-3098-44b3-a5fb-c55403734896 | available | - | 1 | LUKS Boot an instance -> inst1 | ACTIVE Attach volume to instance, mkfs write some data detach volume All passed fine Upload volume to Glance: #openstack image create --disk-format raw --container-format bare --volume 9230d56a-3098-44b3-a5fb-c55403734896 EncVolPlusData Image created, now create a new LUKS volume from image: #cinder create 2 --image 0b900303-3c62-4a97-8eda-20186eea9dbf --volume-type LUKS --name NewVol Volume created -> | d26d3271-0d75-47e1-9f41-f4dde42bfec1 | available | NewVol | 2 | LUKS | true Now attach new volume to instance (failed before) working now # nova volume-attach 0fb7b7e1-a675-481b-8bed-d7bb73a43ae2 d26d3271-0d75-47e1-9f41-f4dde42bfec1 auto Cinder list -> | d26d3271-0d75-47e1-9f41-f4dde42bfec1 | in-use | NewVol | 2 | LUKS | true | 0fb7b7e1-a675-481b-8bed-d7bb73a43ae2 | Mount volume inside instance validate original data exists drums.. # cat flrd/tshefi.txt hello Yep working as expected OK to verify.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHEA-2018:2086