When multiple cinder volumes are created concurrently from the same source image, some of the volumes fail getting created. The number of failures found is 3 out of 64. They are ultimately set to "error" state and the exception noted (in c-vol logs) is "volume already exists"
2016-12-05 01:16:15.317 ^[[01;33mWARNING cinder.volume.manager [^[[01;36mreq-da4f7919-6d29-43c8-abbc-c6c6dfabfc94 ^[[00;36m4d1a35bc9c9e42f79713a478bf01d300 c6e843458e0d4ae08c7c2631e17bd156^[[01;33m] ^[[01;35m^[[01;33mFlow 'volume_create_manager' (b89e0b01-85f9-4ed3-92cf-ae5aae92136b) transitioned into state 'REVERTED' from state 'RUNNING'^[[00m
2016-12-05 01:16:15.318 ^[[01;31mERROR oslo_messaging.rpc.dispatcher [^[[01;36mreq-da4f7919-6d29-43c8-abbc-c6c6dfabfc94 ^[[00;36m4d1a35bc9c9e42f79713a478bf01d300 c6e843458e0d4ae08c7c2631e17bd156^[[01;31m] ^[[01;35m^[[01;31mException during message handling: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvcreate -n volume-82444774-bc9f-413f-b902-bfb6a31e0c24 stack-volumes-lvmdriver-1 -L 1g
Exit code: 5
Stdout: u''
Stderr: u' Logical volume "volume-82444774-bc9f-413f-b902-bfb6a31e0c24" already exists in volume group "stack-volumes-lvmdriver-1"\n'^[[00m
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mTraceback (most recent call last):
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m incoming.message))
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m return self._do_dispatch(endpoint, method, ctxt, args)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m result = func(ctxt, **new_args)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/manager.py", line 632, in create_volume
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m _run_flow()
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/manager.py", line 619, in _run_flow
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m flow_engine.run()
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 230, in run
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m for _state in self.run_iter(timeout=timeout):
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 308, in run_iter
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m failure.Failure.reraise_if_any(fails)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/taskflow/types/failure.py", line 336, in reraise_if_any
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m failures[0].reraise()
[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/taskflow/types/failure.py", line 343, in reraise
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m six.reraise(*self._exc_info)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 82, in _execute_task
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m result = task.execute(**arguments)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 833, in execute
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m **volume_spec)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 768, in _create_from_image
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m image_service
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 645, in _create_from_image_download
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m model_update = self.driver.create_volume(volume_ref)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/drivers/lvm.py", line 348, in create_volume
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m mirror_count)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/volume/drivers/lvm.py", line 184, in _create_volume
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m vg_ref.create_volume(name, size, lvm_type, mirror_count)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/brick/local_dev/lvm.py", line 555, in create_volume
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m run_as_root=True)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/opt/stack/cinder/cinder/utils.py", line 148, in execute
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m return processutils.execute(*cmd, **kwargs)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py", line 389, in execute
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m cmd=sanitized_cmd)
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mProcessExecutionError: Unexpected error while running command.
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mCommand: sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C lvcreate -n volume-82444774-bc9f-413f-b902-bfb6a31e0c24 stack-volumes-lvmdriver-1 -L 1g
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mExit code: 5
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mStdout: u''
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00mStderr: u' Logical volume "volume-82444774-bc9f-413f-b902-bfb6a31e0c24" already exists in volume group "stack-volumes-lvmdriver-1"\n'
^[[01;31m2016-12-05 01:16:15.318 TRACE oslo_messaging.rpc.dispatcher ^[[01;35m^[[00m
2016-12-05 01:16:15.742 ^[[00;32mDEBUG cinder.volume.flows.manager.create_volume [^[[01;36mreq-87e829e6-15bc-4e32-8d7f-b3ce2099899d ^[[00;36m4d1a35bc9c9e42f79713a478bf01d300 c6e843458e0d4ae08c7c2631e17bd156^[[00;32m] ^[[01;35m^[[00;32mCopying metadata from image efe0671a-96da-4edf-95cc-b57ed11d6265 to 6cef8832-6a72-4f8a-84f4-96e882fc496f.^[[00m ^[[00;33mfrom (pid=46470) _handle_bootable_volume_glance_meta /opt/stack/cinder/cinder/volume/flows/manager/create_volume.py:425^[[00m
2016-12-05 01:16:15.743 ^[[00;32mDEBUG cinder.volume.flows.manager.create_volume [^[[01;36mreq-87e829e6-15bc-4e32-8d7f-b3ce2099899d ^[[00;36m4d1a35bc9c9e42f79713a478bf01d300 c6e843458e0d4ae08c7c2631e17bd156^[[00;32m] ^[[01;35m^[[00;32mCreating volume glance metadata for volume 6cef8832-6a72-4f8a-84f4-96e882fc496f backed by image efe0671a-96da-4edf-95cc-b57ed11d6265 with: {'container_format': u'bare', 'min_ram': 0, 'disk_format': u'iso', 'image_name': u'ISO_IMAGE', 'image_id': u'efe0671a-96da-4edf-95cc-b57ed11d6265', 'checksum': u'01545fa976c8367b4f0d59169ac4866c', 'min_disk': 0, 'size': 591396864}.^[[00m ^[[00;33mfrom (pid=46470) _capture_volume_image_metadata /opt/stack/cinder/cinder/volume/flows/manager/create_volume.py:580^[[00m
Affected Version: stable/mitaka
Script used for concurrent volume creation:
export IMG=<img_id>
export TYP=lvmdriver-1
for i in `seq 64`
do cinder create --image-id $IMG --name volume$i --volume-type $TYP 1
done
cinder.conf has following entry for lvmdriver-1. Rest all entries are untouched.
[lvmdriver-1]
lvm_type = default
iscsi_helper = tgtadm
volume_group = stack-volumes-lvmdriver-1
volume_driver = cinder.volume.drivers.lvm.LVMVolumeDriver
volume_backend_name = lvmdriver-1
image_volume_cache_enabled = true <--- addition
c-vol.log file attached in zip for reference.
