During a tempest gate run a nova volumes-extension test failed during creating a volume. Looking at the cinder logs it looks like a cinder failure. It seems that tgtadm failed with code 22 and then subsequent attempts to create the volume fail.
The logs can be found here: http://logs.openstack.org/81/45781/3/check/gate-tempest-devstack-vm-postgres-full/06bccc8
The relevant section from cinder volume log:
2013-09-10 15:02:12.611 21198 ERROR cinder.brick.iscsi.iscsi [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Failed to create iscsi target for volume id:volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgt-admin --update iqn.2010-10.org.openstack:volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c
Exit code: 22
Stdout: 'Command:\n\ttgtadm -C 0 --lld iscsi --op new --mode target --tid 1 -T iqn.2010-10.org.openstack:volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c\nexited with code: 22.\n'
Stderr: 'tgtadm: this target already exists\n'
2013-09-10 15:02:12.611 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-e75c5dd0-eb8b-46e5-b0b8-5b4b17f37010; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.CreateVolumeFromSpecTask;volume:create==1.0; r-bfe064fd-67bd-4312-8d29-078c9a8611ab; 1.0 into state FAILURE with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.612 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-e75c5dd0-eb8b-46e5-b0b8-5b4b17f37010; 6; 0; REVERTING has moved into state REVERTING from state RUNNING flow_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:41
2013-09-10 15:02:12.612 21198 WARNING cinder.taskflow.utils [-] Activating 5 rollbacks due to <cinder.taskflow.utils.FlowFailure object at 0x4ece450>.
2013-09-10 15:02:12.612 21198 DEBUG cinder.taskflow.utils [-] Calling rollback 1: cinder.volume.flows.create_volume.CreateVolumeFromSpecTask;volume:create==1.0 rollback /opt/stack/new/cinder/cinder/taskflow/utils.py:351
2013-09-10 15:02:12.612 21198 DEBUG cinder.taskflow.utils [-] Calling rollback 2: cinder.volume.flows.create_volume.NotifyVolumeActionTask;volume:create, create.start==1.0 rollback /opt/stack/new/cinder/cinder/taskflow/utils.py:351
2013-09-10 15:02:12.613 21198 DEBUG cinder.taskflow.utils [-] Calling rollback 3: cinder.volume.flows.create_volume.ExtractVolumeSpecTask;volume:create==1.0 rollback /opt/stack/new/cinder/cinder/taskflow/utils.py:351
2013-09-10 15:02:12.613 21198 DEBUG cinder.taskflow.utils [-] Calling rollback 4: cinder.volume.flows.create_volume.OnFailureRescheduleTask;volume:create==1.0 rollback /opt/stack/new/cinder/cinder/taskflow/utils.py:351
2013-09-10 15:02:12.613 21198 DEBUG cinder.volume.flows.create_volume [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Updating volume 0ffe5127-ec0d-414f-b741-11c4c9317e1c with {'status': 'creating', 'scheduled_at': datetime.datetime(2013, 9, 10, 15, 2, 12, 613384)} _pre_reschedule /opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py:902
2013-09-10 15:02:12.637 21198 DEBUG cinder.volume.flows.create_volume [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Volume 0ffe5127-ec0d-414f-b741-11c4c9317e1c: re-scheduling SchedulerAPI.create_volume attempt 1 due to An unknown exception occurred. _reschedule /opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py:871
2013-09-10 15:02:12.639 21198 DEBUG cinder.openstack.common.rpc.amqp [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Making asynchronous cast on cinder-scheduler... cast /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:631
2013-09-10 15:02:12.640 21198 DEBUG cinder.openstack.common.rpc.amqp [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] UNIQUE_ID is f94727aa75844fbe99eaf4af6ec2667d. _add_unique_id /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:345
2013-09-10 15:02:12.653 21198 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:88
2013-09-10 15:02:12.653 21198 DEBUG amqp [-] using channel_id: 1 __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:70
2013-09-10 15:02:12.663 21198 DEBUG amqp [-] Channel open _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:420
2013-09-10 15:02:12.664 21198 DEBUG cinder.volume.flows.create_volume [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Volume 0ffe5127-ec0d-414f-b741-11c4c9317e1c: re-scheduled _post_reschedule /opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py:884
2013-09-10 15:02:12.664 21198 ERROR cinder.volume.flows.create_volume [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Unexpected build error:
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume Traceback (most recent call last):
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 172, in run_it
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume result = runner(context, *args, **kwargs)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/taskflow/utils.py", line 260, in __call__
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume self.result = self.task(*args, **kwargs)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py", line 1462, in __call__
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume model_update = self.driver.create_export(context, volume_ref)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 529, in create_export
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume return self._create_export(context, volume)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 564, in _create_export
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume chap_auth)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume File "/opt/stack/new/cinder/cinder/brick/iscsi/iscsi.py", line 177, in create_iscsi_target
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume raise exception.ISCSITargetCreateFailed(volume_id=vol_id)
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume ISCSITargetCreateFailed: An unknown exception occurred.
2013-09-10 15:02:12.664 21198 TRACE cinder.volume.flows.create_volume
2013-09-10 15:02:12.665 21198 DEBUG cinder.taskflow.utils [-] Calling rollback 5: cinder.volume.flows.base.InjectTask;volume:create==1.0 rollback /opt/stack/new/cinder/cinder/taskflow/utils.py:351
2013-09-10 15:02:12.665 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-e75c5dd0-eb8b-46e5-b0b8-5b4b17f37010; 6; 0; FAILURE has moved into state FAILURE from state REVERTING flow_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:41
2013-09-10 15:02:12.665 21198 ERROR cinder.openstack.common.rpc.amqp [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Exception during message handling
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py", line 441, in _process_data
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp **args)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/openstack/common/rpc/dispatcher.py", line 148, in dispatch
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/manager.py", line 222, in create_volume
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp flow.run(context.elevated())
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/decorators.py", line 105, in wrapper
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp return f(self, *args, **kwargs)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 232, in run
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp run_it(r)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 212, in run_it
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp self.rollback(context, cause)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp self.gen.next()
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 172, in run_it
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp result = runner(context, *args, **kwargs)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/utils.py", line 260, in __call__
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp self.result = self.task(*args, **kwargs)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py", line 1462, in __call__
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp model_update = self.driver.create_export(context, volume_ref)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 529, in create_export
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp return self._create_export(context, volume)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 564, in _create_export
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp chap_auth)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/brick/iscsi/iscsi.py", line 177, in create_iscsi_target
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp raise exception.ISCSITargetCreateFailed(volume_id=vol_id)
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp ISCSITargetCreateFailed: An unknown exception occurred.
2013-09-10 15:02:12.665 21198 TRACE cinder.openstack.common.rpc.amqp
2013-09-10 15:02:12.680 21198 DEBUG cinder.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'_member_', u'admin'], u'_context_request_id': u'req-019e2731-c341-4499-ac48-c25c08caaf8c', u'_context_quota_class': None, u'_context_project_name': u'VolumesGetTestXML885495317-tenant', u'_context_service_catalog': [{u'endpoints': [{u'adminURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160', u'region': u'RegionOne', u'internalURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160', u'id': u'3b83b1959ea846c2b2665ad1e4681c4e', u'publicURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160'}], u'endpoints_links': [], u'type': u'compute', u'name': u'nova'}], u'_context_tenant': u'1d7d4e0943cb4fe999e84c2eced85160', u'args': {u'request_spec': {u'volume_id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'volume_properties': {u'status': u'creating', u'volume_type_id': None, u'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'availability_zone': u'nova', u'reservations': [u'ac379850-c9f8-411a-8ce4-fdc735ec0283', u'6f226934-29cb-4d31-9ea1-258e8d4a865f'], u'size': 1, u'attach_status': u'detached', u'display_description': None, u'volume_metadata': [], u'encryption_key_id': None, u'source_volid': None, u'snapshot_id': None, u'display_name': u'Volume-1043660536', u'project_id': u'1d7d4e0943cb4fe999e84c2eced85160', u'id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'metadata': {}}, u'source_volid': None, u'image_id': None, u'volume_type': {}, u'snapshot_id': None, u'resource_properties': {u'status': u'creating', u'volume_type_id': None, u'display_name': u'Volume-1043660536', u'availability_zone': u'nova', u'reservations': [u'ac379850-c9f8-411a-8ce4-fdc735ec0283', u'6f226934-29cb-4d31-9ea1-258e8d4a865f'], u'attach_status': u'detached', u'source_volid': None, u'metadata': {}, u'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'volume_metadata': [], u'display_description': None, u'snapshot_id': None, u'encryption_key_id': None, u'project_id': u'1d7d4e0943cb4fe999e84c2eced85160', u'id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'size': 1}}, u'allow_reschedule': True, u'filter_properties': {u'config_options': {}, u'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'availability_zone': u'nova', u'volume_type': {}, u'request_spec': {u'volume_id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'volume_properties': {u'status': u'creating', u'volume_type_id': None, u'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'availability_zone': u'nova', u'reservations': [u'ac379850-c9f8-411a-8ce4-fdc735ec0283', u'6f226934-29cb-4d31-9ea1-258e8d4a865f'], u'attach_status': u'detached', u'display_description': None, u'metadata': {}, u'encryption_key_id': None, u'volume_metadata': [], u'source_volid': None, u'snapshot_id': None, u'display_name': u'Volume-1043660536', u'project_id': u'1d7d4e0943cb4fe999e84c2eced85160', u'id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'size': 1}, u'volume_type': {}, u'image_id': None, u'source_volid': None, u'snapshot_id': None, u'resource_properties': {u'status': u'creating', u'volume_type_id': None, u'display_name': u'Volume-1043660536', u'availability_zone': u'nova', u'reservations': [u'ac379850-c9f8-411a-8ce4-fdc735ec0283', u'6f226934-29cb-4d31-9ea1-258e8d4a865f'], u'size': 1, u'attach_status': u'detached', u'source_volid': None, u'volume_metadata': [], u'encryption_key_id': None, u'display_description': None, u'snapshot_id': None, u'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'project_id': u'1d7d4e0943cb4fe999e84c2eced85160', u'id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c', u'metadata': {}}}, u'qos_specs': None, u'retry': {u'num_attempts': 2, u'hosts': [u'devstack-precise-hpcloud-az2-242896', u'devstack-precise-hpcloud-az2-242896']}, u'size': 1, u'resource_type': {}, u'metadata': {}}, u'source_volid': None, u'image_id': None, u'snapshot_id': None, u'volume_id': u'0ffe5127-ec0d-414f-b741-11c4c9317e1c'}, u'namespace': None, u'_context_auth_token': '<SANITIZED>', u'_context_timestamp': u'2013-09-10T15:02:11.654827', u'_context_is_admin': False, u'version': u'1.4', u'_context_project_id': u'1d7d4e0943cb4fe999e84c2eced85160', u'_context_user': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'_unique_id': u'70cef6bc91e84f1c950e5ca8fc8e823d', u'_context_read_deleted': u'no', u'_context_user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', u'method': u'create_volume', u'_context_remote_address': u'127.0.0.1'} _safe_log /opt/stack/new/cinder/cinder/openstack/common/rpc/common.py:290
2013-09-10 15:02:12.681 21198 DEBUG cinder.openstack.common.rpc.amqp [-] unpacked context: {'project_name': u'VolumesGetTestXML885495317-tenant', 'user_id': u'f593bf8ff08e4b7c8f7376c80909d2bb', 'roles': [u'_member_', u'admin'], 'timestamp': u'2013-09-10T15:02:11.654827', 'auth_token': '<SANITIZED>', 'remote_address': u'127.0.0.1', 'quota_class': None, 'is_admin': False, 'user': u'f593bf8ff08e4b7c8f7376c80909d2bb', 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160', u'region': u'RegionOne', u'publicURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160', u'internalURL': u'http://127.0.0.1:8774/v2/1d7d4e0943cb4fe999e84c2eced85160', u'id': u'3b83b1959ea846c2b2665ad1e4681c4e'}], u'type': u'compute', u'name': u'nova'}], 'request_id': u'req-019e2731-c341-4499-ac48-c25c08caaf8c', 'project_id': u'1d7d4e0943cb4fe999e84c2eced85160', 'read_deleted': u'no', 'tenant': u'1d7d4e0943cb4fe999e84c2eced85160'} _safe_log /opt/stack/new/cinder/cinder/openstack/common/rpc/common.py:290
2013-09-10 15:02:12.683 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; STARTED has moved into state STARTED from state PENDING flow_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:41
2013-09-10 15:02:12.683 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved into state RUNNING from state STARTED flow_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:41
2013-09-10 15:02:12.684 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.base.InjectTask;volume:create==1.0; r-2b0d4530-5815-4067-86ef-01d7a3598b85; 1.0 into state STARTED with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.684 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.base.InjectTask;volume:create==1.0; r-2b0d4530-5815-4067-86ef-01d7a3598b85; 1.0 into state SUCCESS with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.684 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.OnFailureRescheduleTask;volume:create==1.0; r-b26e3825-6910-4264-b54b-45e611e0fdc3; 1.0 into state STARTED with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.685 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.OnFailureRescheduleTask;volume:create==1.0; r-b26e3825-6910-4264-b54b-45e611e0fdc3; 1.0 into state SUCCESS with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.686 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.ExtractVolumeSpecTask;volume:create==1.0; r-f51abf63-c274-4551-a26f-878917d89244; 1.0 into state STARTED with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.708 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.ExtractVolumeSpecTask;volume:create==1.0; r-f51abf63-c274-4551-a26f-878917d89244; 1.0 into state SUCCESS with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.708 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.NotifyVolumeActionTask;volume:create, create.start==1.0; r-14baa49c-9470-4c4a-9d24-eb124da732c9; 1.0 into state STARTED with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.709 21198 DEBUG cinder.openstack.common.rpc.amqp [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Sending volume.create.start on notifications.info notify /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:670
2013-09-10 15:02:12.709 21198 DEBUG cinder.openstack.common.rpc.amqp [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] UNIQUE_ID is db3c5f563fe0413ca9c725a8094fd865. _add_unique_id /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:345
2013-09-10 15:02:12.712 21198 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:88
2013-09-10 15:02:12.713 21198 DEBUG amqp [-] using channel_id: 1 __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:70
2013-09-10 15:02:12.715 21198 DEBUG amqp [-] Channel open _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:420
2013-09-10 15:02:12.715 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.NotifyVolumeActionTask;volume:create, create.start==1.0; r-14baa49c-9470-4c4a-9d24-eb124da732c9; 1.0 into state SUCCESS with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.716 21198 DEBUG cinder.volume.flows.utils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] LinearFlow: volume_create_manager; f-82f07e00-c573-43ba-be2f-f9afd8c95fcc; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.CreateVolumeFromSpecTask;volume:create==1.0; r-122d5121-8f57-4f24-a725-eb312ddbb2a1; 1.0 into state STARTED with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-10 15:02:12.716 21198 INFO cinder.volume.flows.create_volume [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Volume 0ffe5127-ec0d-414f-b741-11c4c9317e1c: being created using CreateVolumeFromSpecTask._create_raw_volume with specification: {'status': u'creating', 'volume_size': 1, 'volume_name': u'volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c'}
2013-09-10 15:02:12.717 21198 DEBUG cinder.openstack.common.processutils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate -n volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c stack-volumes -L 1g execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:142
2013-09-10 15:02:12.823 21198 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /opt/stack/new/cinder/cinder/openstack/common/periodic_task.py:176
2013-09-10 15:02:12.824 21198 DEBUG cinder.manager [-] Notifying Schedulers of capabilities ... _publish_service_capabilities /opt/stack/new/cinder/cinder/manager.py:135
2013-09-10 15:02:12.824 21198 DEBUG cinder.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... fanout_cast /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:640
2013-09-10 15:02:12.824 21198 DEBUG cinder.openstack.common.rpc.amqp [-] UNIQUE_ID is b6a71bf0e21e4c4d9781f30d8abaa3db. _add_unique_id /opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py:345
2013-09-10 15:02:12.828 21198 DEBUG amqp [-] Closed channel #1 _do_close /usr/local/lib/python2.7/dist-packages/amqp/channel.py:88
2013-09-10 15:02:12.829 21198 DEBUG amqp [-] using channel_id: 1 __init__ /usr/local/lib/python2.7/dist-packages/amqp/channel.py:70
2013-09-10 15:02:12.831 21198 DEBUG amqp [-] Channel open _open_ok /usr/local/lib/python2.7/dist-packages/amqp/channel.py:420
2013-09-10 15:02:12.832 21198 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /opt/stack/new/cinder/cinder/openstack/common/periodic_task.py:176
2013-09-10 15:02:12.832 21198 INFO cinder.volume.manager [-] Updating volume status
2013-09-10 15:02:12.832 21198 DEBUG cinder.volume.drivers.lvm [-] Updating volume stats _update_volume_stats /opt/stack/new/cinder/cinder/volume/drivers/lvm.py:335
2013-09-10 15:02:12.832 21198 DEBUG cinder.openstack.common.processutils [-] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf env LC_ALL=C LANG=C vgs --noheadings --unit=g -o name,size,free,lv_count,uuid --separator : --nosuffix stack-volumes execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:142
2013-09-10 15:02:12.913 21198 DEBUG cinder.openstack.common.processutils [req-b3d7f540-b8a0-4bcb-b855-37cb26c51954 d22c4ba427b34d31951c68eb97d598ba 886a92c191bc4043b49b3080d96d3e59] Running cmd (subprocess): sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgt-admin --show execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:142
2013-09-10 15:02:12.934 21198 DEBUG cinder.openstack.common.processutils [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Result was 5 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:167
2013-09-10 15:02:12.934 21198 ERROR cinder.brick.local_dev.lvm [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Error creating Volume
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm Traceback (most recent call last):
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 368, in create_volume
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm run_as_root=True)
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm File "/opt/stack/new/cinder/cinder/utils.py", line 142, in execute
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm return processutils.execute(*cmd, **kwargs)
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm File "/opt/stack/new/cinder/cinder/openstack/common/processutils.py", line 173, in execute
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm cmd=' '.join(cmd))
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm ProcessExecutionError: Unexpected error while running command.
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate -n volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c stack-volumes -L 1g
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm Exit code: 5
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm Stdout: ''
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm Stderr: ' Logical volume "volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c" already exists in volume group "stack-volumes"\n'
2013-09-10 15:02:12.934 21198 TRACE cinder.brick.local_dev.lvm
2013-09-10 15:02:12.936 21198 ERROR cinder.brick.local_dev.lvm [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] Cmd :sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate -n volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c stack-volumes -L 1g
2013-09-10 15:02:12.936 21198 ERROR cinder.brick.local_dev.lvm [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] StdOut :
2013-09-10 15:02:12.936 21198 ERROR cinder.brick.local_dev.lvm [req-019e2731-c341-4499-ac48-c25c08caaf8c f593bf8ff08e4b7c8f7376c80909d2bb 1d7d4e0943cb4fe999e84c2eced85160] StdErr : Logical volume "volume-0ffe5127-ec0d-414f-b741-11c4c9317e1c" already exists in volume group "stack-volumes"
Interesting, this reveals something we've been talking about a bit. It looks like we tried to create the same LVM twice here, most likely an issue with the retry mechanism in the create flow.