encrypted volume is in "in-use" state while boot from volume failed

Looks like a Nova problem. We need the logs from this, but my assumption is the Cinder volume is indeed attached and therefore in-use, so Cinder is working as expected.

I am not sure if the expectation on the Nova side is that they fully rollback and clean up the Cinder volume in case of a failure like this, or if it is kept around as a means to troubleshoot what happened.

From nova-compute:
==================

ey not defined
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] Traceback (most recent call last):
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1856, in _do_build_and_run_instance
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] filter_properties)
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2035, in _build_and_run_instance
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] phase=fields.NotificationPhase.ERROR, exception=e)
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] self.force_reraise()
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] six.reraise(self.type_, self.value, self.tb)
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2010, in _build_and_run_instance
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] instance=instance)
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib64/python2.7/contextlib.py", line 35, in __exit__
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] self.gen.throw(type, value, traceback)
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2219, in _build_resources
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] reason=six.text_type(exc))
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702] BuildAbortException: Build of instance 1065e02d-b199-4071-8a46-93c3f0f83702 aborted: keymgr.fixed_key not def
ined
2018-01-25 14:36:58.781 1 ERROR nova.compute.manager [instance: 1065e02d-b199-4071-8a46-93c3f0f83702]

From volume.log:
================

Stdout: u''
Stderr: u'Device /dev/sda is not a valid LUKS device.\nCommand failed with code 22: Invalid argument\n' loop /usr/lib/python2.7/site-packages/oslo_privsep/daemon.py:449
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/oslo_privsep/daemon.py", line 445, in loop
    reply = s...

This looks valid to me. During the boot process, it's failing to attach the volume because CONF.key_manager.fixed_key = None. We should handle that exception and roll back the volume status via Cinder calls as things are getting cleaned up.

2018-01-25 14:36:56.716 1 WARNING nova.volume.cinder [req-9e16e37f-6bdb-445d-8024-1184a3dd7c45 db1a02ae2f5a4f4db07c1f62958ef9e7 ef184f071981405d9071c7ca33a40303 - default default] The support for the Cinder API v2 is deprecated, please upgrade to Cinder API v3.
2018-01-25 14:36:56.717 1 DEBUG cinderclient.v2.client [req-9e16e37f-6bdb-445d-8024-1184a3dd7c45 db1a02ae2f5a4f4db07c1f62958ef9e7 ef184f071981405d9071c7ca33a40303 - default default] REQ: curl -g -i -X GET http://172.17.1.14:8776/v2/ef184f071981405d9071c7ca33a40303/volumes/58804519-e8fc-442b-ad7c-9066abf103d7/encryption -H "User-Agent: python-cinderclient" -H "X-OpenStack-Request-ID: req-9e16e37f-6bdb-445d-8024-1184a3dd7c45" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}671e4eff9977526aedde7b4cf4a18083a16178a5" _http_log_request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:375
2018-01-25 14:36:57.506 1 DEBUG cinderclient.v2.client [req-9e16e37f-6bdb-445d-8024-1184a3dd7c45 db1a02ae2f5a4f4db07c1f62958ef9e7 ef184f071981405d9071c7ca33a40303 - default default] RESP: [200] Date: Thu, 25 Jan 2018 14:36:56 GMT Server: Apache x-compute-request-id: req-d826157e-23b3-4d0b-947c-5688ebbdb4b4 x-openstack-request-id: req-d826157e-23b3-4d0b-947c-5688ebbdb4b4 Vary: Accept-Encoding Content-Encoding: gzip Content-Length: 151 Content-Type: application/json
RESP BODY: {"cipher": "aes-xts-plain64", "encryption_key_id": "00000000-0000-0000-0000-000000000000", "provider": "nova.volume.encryptors.luks.LuksEncryptor", "key_size": 512, "control_location": "front-end"}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneauth1/session.py:423
2018-01-25 14:36:57.507 1 DEBUG cinderclient.v2.client [req-9e16e37f-6bdb-445d-8024-1184a3dd7c45 db1a02ae2f5a4f4db07c1f62958ef9e7 ef184f071981405d9071c7ca33a40303 - default default] GET call to cinderv2 for http://172.17.1.14:8776/v2/ef184f071981405d9071c7ca33a40303/volumes/58804519-e8fc-442b-ad7c-9066abf103d7/encryption used request id req-d826157e-23b3-4d0b-947c-5688ebbdb4b4 request /usr/lib/python2.7/site-packages/keystoneauth1/session.py:727
2018-01-25 14:36:57.508 1 DEBUG os_brick.encryptors [req-9e16e37f-6bdb-445d-8024-1184a3dd7c45 db1a02ae2f5a4f4db07c1f62958ef9e7 ef184f071981405d9071c7ca33a40303 - default default] Using volume encryption metadata '{u'cipher': u'aes-xts-plain64', u'encryption_key_id': u'00000000-0000-0000-0000-000000000000', u'provider': u'nova.volume.encryptors.luks.LuksEncryptor', u'key_size': 512, u'control_location': u'front-end'}' for connection: {u'driver_volume_type': u'iscsi', 'connector': {'platform': 'x86_64', 'host': 'compute-0.localdomain', 'do_local_attach': False, 'ip': '172.17.1.13', 'os_type': 'linux2', 'multipath': False, 'initiator': u'iqn.1994-05.com.redhat:8f64791b5192'}, 'serial': u'58804519-e8fc-442b-ad7c-9066abf103d7', u'data': {u'access_mode': u'rw', u'target_discovered': False, u'encrypted': True, u'qos_specs': None, u'target_iqn': u'iqn.2010-10.org.opens...

Adding more notes on what I think needs to be done. I did some digging and found that what's happening is the volume is connected to the instance in the libvirt driver, *then* it tries to attach the encryptor and the encryptor attach fails because the fixed_key config option hasn't been set. So the instance spawn fails but the volume remains connected. We need to try-except around the encryptor attach attempt and disconnect the volume before re-raising.

1. Create a new, more specific NovaException for the missing fixed key, for example "FixedKeyNotDefined" and correct the message (it should be "key_manager.fixed_key") [1]

2. Catch FixedKeyNotDefined in the libvirt driver when trying to attach the encryptor and disconnect the volume before re-raising [2]

[1] https://github.com/openstack/nova/blob/233285d/nova/keymgr/conf_key_mgr.py#L67
[2] https://github.com/openstack/nova/blob/233285d/nova/virt/libvirt/driver.py#L1227

On second thought, it might be best to catch all Exception during the encryptor attach attempt and just re-raise that. Because if the encryptor attach fails for any reason, we need to disconnect the volume.

I think the second thought is better, which really covers all possible failures and rollback the volume to normal status.

If this is OK, I will try to fix it.

After disconnect volume, the volume will keep in "reserved" status. Not only this case, in fact once instance build abort(like bind port fail), the status of volume will be set to "reserved". I'm really not sure whether it's our expected status or not.

IMO, we should unreserve volume if the volume is root disk when fail to boot an instance from volume.

Fix proposed to branch: master
Review: https://review.openstack.org/549469

Change abandoned by Balazs Gibizer (<email address hidden>) on branch: master
Review: https://review.opendev.org/549469
Reason: This patch is stale. Feel free to restore it (or gibi on IRC to do so) if you are still working on this.

This is actually invalid, failure during spawn should actually result in the volume remaining attached and in-use as happens now. We could call _disconnect_volume when we hit an error during attach_encryptor but I believe we should also clean this up when the instance is destroyed anyway.