'in use' error when Nova volume encryptors format cinder volumes

[Tom Barron]

Tempest scenario TestEncryptedCinderVolumes has been silently skipped when run with NetApp iSCSI cinder volume drivers because they did not set the 'encrypted' key in the connection_info['data'] dict in their initialize_connection methods. Change
https://review.openstack.org/#/c/193673/ - which sets the encrypted flag generically, in the VolumeManager's initialize_connection, on the basis of the volume.encryption_key_id value - causes this test to actually run its encryption providers and exposes a problem in LuksEncryptor:_format_volume() for these iSCSI volumes.

In TestEncryptedCinderVolumes we get the following exception:

2015-06-29 06:27:18.866 ERROR nova.virt.libvirt.driver [req-7124728f-64b7-4951-806b-10901bb2f6b9 TestEncryptedCinderVolumes-1766245790 TestEncryptedCinderVolumes-1100414243] [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Failed to attach volume at mountpoint: /dev/vdb
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Traceback (most recent call last):
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 1082, in attach_volume
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] encryptor.attach_volume(context, **encryption)
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] File "/opt/stack/new/nova/nova/volume/encryptors/luks.py", line 113, in attach_volume
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] self._format_volume(passphrase, **kwargs)
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] File "/opt/stack/new/nova/nova/volume/encryptors/luks.py", line 78, in _format_volume
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] check_exit_code=True, run_as_root=True)
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] File "/opt/stack/new/nova/nova/utils.py", line 229, in execute
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] return processutils.execute(*cmd, **kwargs)
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py", line 260, in execute
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] cmd=sanitized_cmd)
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] ProcessExecutionError: Unexpected error while running command.
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf cryptsetup --batch-mode luksFormat --key-file=- --cipher aes-xts-plain64 --key-size 512 /dev/sdh
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Exit code: 5
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Stdout: u''
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c] Stderr: u'Cannot format device /dev/sdh which is still in use.\n'
2015-06-29 06:27:18.866 12852 ERROR nova.virt.libvirt.driver [instance: 4a5dd4fd-78f8-42ea-8736-406ccb178d7c]

This is on master, corresponding code is: https://github.com/openstack/nova/blob/master/nova/volume/encryptors/luks.py#L78

[Matt Riedemann (mriedem)]

Any idea what's causing the in-use when this happens?

[Matt Riedemann (mriedem)]

Could be similar to bug 1374458 where we just added a retry of 3 when trying to close the volume:

https://review.openstack.org/#/c/124418/

[Matt Riedemann (mriedem)]

Here is the netapp iscsi third party CI log where this failed:

http://dcf901611175aa43f968-c54047c910227e27e1d6f03bb1796fd7.r95.cf5.rackcdn.com/73/193673/3/check/cinder-cDOT-iSCSI/e911b71/screen-n-cpu.txt

[Matt Riedemann (mriedem)]

It's using cryptsetup 1.6.1:

ii cryptsetup 2:1.6.1-1ubuntu1 amd64 disk encryption support - startup scripts
ii cryptsetup-bin 2:1.6.1-1ubuntu1 amd64 disk encryption support - command line tools

I was wondering because I was searching threads for issues with cryptsetup returning exit code 5 and found this:

https://bbs.archlinux.org/viewtopic.php?id=186296

Where they were talking about issues after 1.6.4, but we wouldn't be hitting that.

[Matt Riedemann (mriedem)]

I also see this in the failed test run:

2015-06-29 06:27:17.930 INFO nova.volume.encryptors.luks [req-7124728f-64b7-4951-806b-10901bb2f6b9 TestEncryptedCinderVolumes-1766245790 TestEncryptedCinderVolumes-1100414243] /dev/sdh is not a valid LUKS device; formatting device for first use

[Matt Riedemann (mriedem)]

Here is the patch: https://review.openstack.org/#/c/197721/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/197721
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=3aabe378b128163b0e4e443a38a8d99e8bde1006
Submitter: Jenkins
Branch: master

commit 3aabe378b128163b0e4e443a38a8d99e8bde1006
Author: Matt Riedemann <email address hidden>
Date: Wed Jul 1 12:37:29 2015 -0700

    Try luksFormat up to 3 times in case the device is in use

    Cinder change I03f8cae05cc117e14f7482115de685fc9f3fa54a is failing for
    some volume driver third party CI like NetApp iSCSI because the device
    is in use when formatting the device for LUKS.

    This change adds a retry counter to the luksFormat command execution
    like we did in commit eef97cdf4bb7f426d7feb394ef54510db8b1656b for
    closing the volume and hitting intermittent in-use issues.

    Closes-Bug: #1470562
    Related-Bug: #1440227

    Change-Id: I0cb32a6f9fbe68ae033ad00534512aa5d82a417b