Volume create tgtadmin fails with error code 22

[Matthew Treinish]

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"

[John Griffith (john-griffith)]

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.

[Attila Fazekas (afazekas)]

Similar issue:

http://logs.openstack.org/74/46774/2/gate/gate-tempest-devstack-vm-full/733f325/logs/screen-c-vol.txt.gz#_2013-09-16_19_08_55_177
http://logs.openstack.org/74/46774/2/gate/gate-tempest-devstack-vm-full/733f325/console.html

[Matthew Treinish (treinish)]

logstash.openstack.org query: @message:"with code 22" AND @fields.filename:"logs/screen- c-vol.txt" AND @fields.build_status:"FAILURE"

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/47513
Committed: http://github.com/openstack/cinder/commit/90f200682c94b1e4b69e04befc045e7ae9111cf7
Submitter: Jenkins
Branch: master

commit 90f200682c94b1e4b69e04befc045e7ae9111cf7
Author: John Griffith <email address hidden>
Date: Thu Sep 19 20:47:22 2013 -0600

    Add a retry to create_iscsi_target for LVM

    There's a bug in the tgt driver where under certain
    conditions where a race condition is present that can
    result in tgtadm attempting re-use a target ID.

    Testing this it seems that a retry will address this nicely
    and cause tgtd to grab a new target ID and things are ok.

    This patch adds a simple check/retry mechanism around the
    iscsi_target_create in the LVM driver to catch this issue and
    deal with it.

    There are a number of bugs that it appears can be attributed to
    this, but this patch is associated with the most predominant
    clear cut version.

    Closes-Bug #1223469

    Change-Id: I5126009f196adcafad55e73ff99a59262dd93dfe

[Morgan Fainberg (mdrnstm)]

Reopening as discussed in IRC with jgriffith. Links / logs following:

Looks like Retry wasn't hit.

At 18:38:18.942 and 18:38:20:
http://logs.openstack.org/47/45447/10/check/gate-tempest-devstack-vm-full/28cde74/console.html
http://logs.openstack.org/47/45447/10/check/gate-tempest-devstack-vm-full/28cde74/logs/screen-c-vol.txt.gz

Relevant section:
2013-09-24 18:38:18.942 25131 DEBUG cinder.openstack.common.processutils [req-114e2f9e-028a-4942-8322-7963bc9adb5a ee05f6fe5e0b43d09faa81ce4f301b35 b715e280bcc14b1ab311fb8c216097af] Result was 22 execute /opt/stack/new/cinder/cinder/openstack/common/processutils.py:167
2013-09-24 18:38:18.943 25131 ERROR cinder.brick.iscsi.iscsi [req-114e2f9e-028a-4942-8322-7963bc9adb5a ee05f6fe5e0b43d09faa81ce4f301b35 b715e280bcc14b1ab311fb8c216097af] Failed to create iscsi target for volume id:volume-79c72d47-da80-4b62-b6c3-e05c2847a804: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf tgt-admin --update iqn.2010-10.org.openstack:volume-79c72d47-da80-4b62-b6c3-e05c2847a804
Exit code: 22
Stdout: 'Command:\n\ttgtadm -C 0 --lld iscsi --op new --mode target --tid 2 -T iqn.2010-10.org.openstack:volume-79c72d47-da80-4b62-b6c3-e05c2847a804\nexited with code: 22.\n'
Stderr: 'tgtadm: this target already exists\n'
2013-09-24 18:38:18.943 25131 DEBUG cinder.volume.flows.utils [req-114e2f9e-028a-4942-8322-7963bc9adb5a ee05f6fe5e0b43d09faa81ce4f301b35 b715e280bcc14b1ab311fb8c216097af] LinearFlow: volume_create_manager; f-5f07bc3e-84cc-4744-8a24-2abd5807efd9; 6; 0; RUNNING has moved Runner: cinder.volume.flows.create_volume.CreateVolumeFromSpecTask;volume:create==1.0; r-96408cb5-00e4-45d6-8f5e-e193ffa45532; 1.0 into state FAILURE with result: None task_log_change /opt/stack/new/cinder/cinder/volume/flows/utils.py:49
2013-09-24 18:38:18.943 25131 DEBUG cinder.volume.flows.utils [req-114e2f9e-028a-4942-8322-7963bc9adb5a ee05f6fe5e0b43d09faa81ce4f301b35 b715e280bcc14b1ab311fb8c216097af] LinearFlow: volume_create_manager; f-5f07bc3e-84cc-4744-8a24-2abd5807efd9; 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-24 18:38:18.944 25131 WARNING cinder.taskflow.utils [-] Activating 5 rollbacks due to <cinder.taskflow.utils.FlowFailure object at 0x469a890>.
2013-09-24 18:38:18.944 25131 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-24 18:38:18.944 25131 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-24 18:38:18.944 25131 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-24 18:38:18.945 25131 DEBUG cinder.taskflow.utils [-] Calling rollback 4: cinder.volume.flows.create_volume.OnFailureChangeStatusTask;volume:create==1.0 rollback /opt/stack/new/...

[John Griffith (john-griffith)]

I think we can close this. Between the initial patch and the added fix here: https://review.openstack.org/#/c/48970/

The error will still show up in the logs, however based on the logs the last couple of days the recovery process that was added seems to be doing the trick. Of course we'll keep an eye out and reopen if necessary.

[Joe Gordon (jogo)]

A spot check of the cases of this "with code 22" after the Fix confirm John's assessment.

[Thomas Herve (therve)]

We got 15 hits over the past 5 days in the gate with that error. Is it possible that it reappeared?

[Davanum Srinivas (DIMS) (dims-v)]

This has definitely started happening again. example
http://logs.openstack.org/40/66740/4/check/check-tempest-dsvm-full/2734142/testr_results.html.gz
http://logs.openstack.org/93/68793/1/check/check-tempest-dsvm-postgres-full/a93999c/logs/screen-c-vol.txt.gz

Logstash query:
"Failed to update iscsi target" AND filename:"logs/screen-c-vol.txt"

20 hits in 7 days.

[John Griffith (john-griffith)]

Aha...

Change-Id: I185a90ffc4d50dd9f91381df07289476fa792043
Introduced a new exception and didn't add it to my original fix for this. I'll submit a patch in just a moment.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/69026
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=18f8f5be94aae3b1747b143479ea1b188872f000
Submitter: Jenkins
Branch: master

commit 18f8f5be94aae3b1747b143479ea1b188872f000
Author: John Griffith <email address hidden>
Date: Fri Jan 24 14:51:21 2014 -0700

    Catch new iscsi exception

    A while back we fixed up a target create/update error
    that was identified in the gating tests:
        https://review.openstack.org/#/c/47513/

    Since then a new patch was introduced to to the update and separate
    it so that it could easily be used in other places.
        https://review.openstack.org/#/c/58599/

    The problem is this added a new exception "TargetUpdate" and
    didn't add this to the except block that we have.

    This patch changes the catch block to handle the new exception and
    do the retry, thereby putting the original fix back in place.

    Change-Id: I1ed1bc6f4249f99a36b1168f9fec0b6b74482acf
    Closes-Bug: 1223469

[Mauro S M Rodrigues (maurorodrigues)]

Do we need something from tempest side? If not I'll close this bug