Bug 1573870 - Attaching an encrypted Cinder vol created from an image (created from another encrypted vol upload)fails
Summary: Attaching an encrypted Cinder vol created from an image (created from another...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-cinder
Version: 13.0 (Queens)
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: rc
: 13.0 (Queens)
Assignee: Eric Harney
QA Contact: Avi Avraham
Kim Nylander
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-02 12:08 UTC by Tzach Shefi
Modified: 2020-09-01 14:33 UTC (History)
19 users (show)

Fixed In Version: openstack-cinder-12.0.1-0.20180418194614.c476898.el7ost
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-06-27 13:54:52 UTC
Target Upstream Version:
eharney: needinfo-


Attachments (Terms of Use)
Logs (1.47 MB, application/zip)
2018-05-02 12:08 UTC, Tzach Shefi
no flags Details


Links
System ID Priority Status Summary Last Updated
Launchpad 1764125 None None None 2018-05-17 12:33:15 UTC
OpenStack gerrit 571010 'None' MERGED Fix handling of 'cinder_encryption_key_id' image metadata 2020-09-01 14:32:40 UTC
Red Hat Product Errata RHEA-2018:2086 None None None 2018-06-27 13:55:51 UTC

Description Tzach Shefi 2018-05-02 12:08:35 UTC
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.

Comment 1 Matthew Booth 2018-05-04 11:55:40 UTC
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]

Comment 2 Matthew Booth 2018-05-04 12:10:21 UTC
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?

Comment 3 Lee Yarwood 2018-05-11 11:58:56 UTC
(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?

Comment 4 Tzach Shefi 2018-05-16 19:44:55 UTC
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

Comment 6 Lee Yarwood 2018-05-17 12:33:16 UTC
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!

Comment 8 Eric Harney 2018-05-23 21:05:53 UTC
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

Comment 14 Tzach Shefi 2018-06-04 08:41:22 UTC
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.

Comment 21 Tzach Shefi 2018-06-05 11:01:34 UTC
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.

Comment 25 errata-xmlrpc 2018-06-27 13:54:52 UTC
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


Note You need to log in before you can comment on or make changes to this bug.