InvalidVolume exceptions due to source volume status

[Silvan Kaiser]

Quobyte CI recently started throwing a range of InvalidVolume exceptions during tempest runs. These exceptions do not fail the tests but are an unnecessary hassle in the volume.log file.
Examples:

{},migration_status=None,multiattach=False,previous_status=None,project_id='62011d2241ea47d9ab3b416c0b39ef90',provider_auth=None,provider_geometry=None,provider_id=None,provider_location='78.46.57.153:7861/quobyteci_test_volume',replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2017-02-11T00:11:14Z,size=1,snapshot_id=None,snapshots=<?>,source_volid=99e4d61c-a787-4530-81ce-3ae893952838,status='creating',terminated_at=None,updated_at=2017-02-11T00:11:14Z,user_id='15a6db99d85146ed936260537ca87651',volume_attachment=<?>,volume_type=VolumeType(1df9d576-ad03-4afd-9fbc-2ae922d85ec1),volume_type_id=1df9d576-ad03-4afd-9fbc-2ae922d85ec1), 'context': <cinder.context.RequestContext object at 0x7fe51c60c710>}, 'provides': Volume(_name_id=None,admin_metadata={},attach_status='detached',availability_zone='nova',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2017-02-11T00:11:13Z,deleted=False,deleted_at=None,display_description=None,display_name='image-ee0f4f55-dc6e-4e64-ba70-5112c566236f',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host='refs-changes-14-432414-2@Quobyte#Quobyte',id=8322d35e-9268-4918-9226-c504f198d7ce,launched_at=None,metadata={},migration_status=None,multiattach=False,previous_status=None,project_id='62011d2241ea47d9ab3b416c0b39ef90',provider_auth=None,provider_geometry=None,provider_id=None,provider_location='78.46.57.153:7861/quobyteci_test_volume',replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2017-02-11T00:11:14Z,size=1,snapshot_id=None,snapshots=<?>,source_volid=99e4d61c-a787-4530-81ce-3ae893952838,status='creating',terminated_at=None,updated_at=2017-02-11T00:11:14Z,user_id='15a6db99d85146ed936260537ca87651',volume_attachment=<?>,volume_type=VolumeType(1df9d576-ad03-4afd-9fbc-2ae922d85ec1),volume_type_id=1df9d576-ad03-4afd-9fbc-2ae922d85ec1)}
           |__Flow 'volume_create_manager'
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager Traceback (most recent call last):
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager result = task.execute(**arguments)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 875, in execute
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager context, volume, **volume_spec)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 492, in _create_from_source_volume
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager model_update = self.driver.create_cloned_volume(volume, srcvol_ref)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager return f(*args, **kwargs)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/drivers/quobyte.py", line 175, in create_cloned_volume
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager self._create_cloned_volume(volume, src_vref)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/drivers/remotefs.py", line 939, in _create_cloned_volume
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager raise exception.InvalidVolume(msg)
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager InvalidVolume: Source volume status must be 'available', or 'backing-up' but is: downloading.
2017-02-11 00:11:16.745 26851 ERROR cinder.volume.manager
2017-02-11 00:11:16.748 26851 DEBUG cinder.volume.manager [req-524fc396-7a71-4bef-b53d-89221644d42e - -] Task 'cinder.volume.flows.manager.create_

2017-02-11 00:11:16.815 26851 WARNING cinder.volume.manager [req-524fc396-7a71-4bef-b53d-89221644d42e - -] Flow 'volume_create_manager' (7a8dbb9a-b197-4cdf-9758-fdf641a11b15) transitioned into state 'REVERTED' from state 'RUNNING'
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager [req-524fc396-7a71-4bef-b53d-89221644d42e - -] Failed to clone volume 99e4d61c-a787-4530-81ce-3ae893952838 for image ee0f4f55-dc6e-4e64-ba70-5112c566236f.
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager Traceback (most recent call last):
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/manager.py", line 1250, in _clone_image_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager self.create_volume(ctx, image_volume, allow_reschedule=False)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "<decorator-gen-235>", line 2, in create_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/objects/cleanable.py", line 207, in wrapper
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager result = f(*args, **kwargs)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/manager.py", line 654, in create_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager _run_flow()
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/manager.py", line 646, in _run_flow
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager flow_engine.run()
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 247, in run
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager for _state in self.run_iter(timeout=timeout):
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 340, in run_iter
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager failure.Failure.reraise_if_any(er_failures)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/types/failure.py", line 336, in reraise_if_any
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager failures[0].reraise()
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/types/failure.py", line 343, in reraise
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager six.reraise(*self._exc_info)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager result = task.execute(**arguments)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 875, in execute
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager context, volume, **volume_spec)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 492, in _create_from_source_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager model_update = self.driver.create_cloned_volume(volume, srcvol_ref)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 271, in inner
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager return f(*args, **kwargs)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/drivers/quobyte.py", line 175, in create_cloned_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager self._create_cloned_volume(volume, src_vref)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager File "/opt/stack/cinder/cinder/volume/drivers/remotefs.py", line 939, in _create_cloned_volume
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager raise exception.InvalidVolume(msg)
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager InvalidVolume: Source volume status must be 'available', or 'backing-up' but is: downloading.
2017-02-11 00:11:17.080 26851 ERROR cinder.volume.manager
2017-02-11 00:11:17.082 26851 DEBUG cinder.coordination [req-524fc396-7a71-4bef-b53d-89221644d42e - -] Lock "8322d35e-9268-4918-9226-c504f198d7ce-delete_volume" acquired by "delete_volume" :: waited 0.000s _synchronized /opt/stack/cinder/cinder/coordination.py:300

I'm attaching a complete example test run.

[Silvan Kaiser (2-silvan)]

This also hits other CIs, e.g. a virtuozzo (this example at http://openstack-3rd-party-storage-ci-logs.virtuozzo.com/82/435082/1/check/dsvm-tempest-kvm/57916aa/logs/screen-c-vol.txt.gz):

2017-02-16 22:42:14.795 50750 WARNING cinder.volume.manager [req-395e8bb9-c4b9-4718-932a-140e6dbf3f6f - -] Task 'cinder.volume.flows.manager.create_volume.CreateVolumeFromSpecTask;volume:create' (7f51f0c3-d228-407d-b3b1-1b9957a64ae4) transitioned into state 'FAILURE' from state 'RUNNING'
5 predecessors (most recent first):
  Atom 'cinder.volume.flows.manager.create_volume.NotifyVolumeActionTask;volume:create, create.start' {'intention': 'EXECUTE', 'state': 'SUCCESS', 'requires': {'volume': Volume(_name_id=None,admin_metadata={},attach_status='detached',availability_zone='nova',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2017-02-16T22:42:09Z,deleted=False,deleted_at=None,display_description=None,display_name='image-3baa5599-c31f-4ce3-aca1-c6953963b56e',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host='localhost@vstorage-qcow2#vstorage-qcow2',id=cf9d47f0-4303-4bf1-968f-a6e37dd85fe6,launched_at=None,metadata={Type='Test'},migration_status=None,multiattach=False,previous_status=None,project_id='60a69e5bb546417482f85e90dfabc241',provider_auth=None,provider_geometry=None,provider_id=None,provider_location='testcluster_fltatnkl9y',replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2017-02-16T22:42:09Z,size=1,snapshot_id=None,snapshots=<?>,source_volid=9805342a-ab06-46b8-8685-69717e9e2c6b,status='creating',terminated_at=None,updated_at=2017-02-16T22:42:09Z,user_id='87542d50568c425d9d332b046b956861',volume_attachment=<?>,volume_type=VolumeType(a6858533-87cb-40b6-b8d8-5f1c54613cad),volume_type_id=a6858533-87cb-40b6-b8d8-5f1c54613cad), 'context': <cinder.context.RequestContext object at 0x839af10>}, 'provides': None}
  |__Atom 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' {'intention': 'EXECUTE', 'state': 'SUCCESS', 'requires': {'volume': Volume(_name_id=None,admin_metadata={},attach_status='detached',availability_zone='nova',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2017-02-16T22:42:09Z,deleted=False,deleted_at=None,display_description=None,display_name='image-3baa5599-c31f-4ce3-aca1-c6953963b56e',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host='localhost@vstorage-qcow2#vstorage-qcow2',id=cf9d47f0-4303-4bf1-968f-a6e37dd85fe6,launched_at=None,metadata={Type='Test'},migration_status=None,multiattach=False,previous_status=None,project_id='60a69e5bb546417482f85e90dfabc241',provider_auth=None,provider_geometry=None,provider_id=None,provider_location='testcluster_fltatnkl9y',replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2017-02-16T22:42:09Z,size=1,snapshot_id=None,snapshots=<?>,source_volid=9805342a-ab06-46b8-8685-69717e9e2c6b,status='creating',terminated_at=None,updated_at=2017-02-16T22:42:09Z,user_id='87542d50568c425d9d332b046b956861',volume_attachment=<...

[Lucian Petrut (petrutlucian94)]

I think this is the cause: https://bugs.launchpad.net/cinder/+bug/1685277

[Silvan Kaiser (2-silvan)]

Hmm, after some checking I get the same impression.