volume creation randomly fails - Exception during message handling

[Hrushikesh]

With already 300 volumes in play, the next set of 50 instances + volumes provisioning fails on volume creation. While creating a set of 50 volumes in a row, one of the volumes creation fails, but continues on creating the remaining. See the log below for details

2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-1f273e27-3b79-4a0e-b467-ea759f83bf42: created successfully
2013-06-15 01:11:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-5e1d7615-5a7f-4d6e-bf39-48e183d15ccd: creating
2013-06-15 01:11:05 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-b8f4bc42-008f-4ae0-8966-c516a59116e8
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-becebbb4-d054-4cfa-bc12-4e2c765a1501: created successfully
2013-06-15 01:11:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-105fb8dc-714f-44e0-9a7f-eb16bbba0f16: creating
2013-06-15 01:11:05 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-2f5ba4f1-79c8-45b0-bb2e-dc2006625536
2013-06-15 01:11:05 ERROR [cinder.volume.iscsi] Failed to create iscsi target for volume id:volume-b8f4bc42-008f-4ae0-8966-c516a59116e8.
2013-06-15 01:11:05 ERROR [cinder.volume.manager] volume volume-b8f4bc42-008f-4ae0-8966-c516a59116e8: create failed
2013-06-15 01:11:05 ERROR [cinder.openstack.common.rpc.amqp] Exception during message handling
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py", line 430, in _process_data
    rval = self.proxy.dispatch(ctxt, version, method, **args)
  File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/dispatcher.py", line 133, in dispatch
    return getattr(proxyobj, method)(ctxt, **kwargs)
  File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 282, in create_volume
    LOG.error(_("volume %s: create failed"), volume_ref['name'])
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 274, in create_volume
    model_update = self.driver.create_export(context, volume_ref)
  File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/lvm.py", line 484, in create_export
    chap_auth)
  File "/usr/lib/python2.7/dist-packages/cinder/volume/iscsi.py", line 168, in create_iscsi_target
    raise exception.ISCSITargetCreateFailed(volume_id=vol_id)
ISCSITargetCreateFailed: Failed to create iscsi target for volume volume-b8f4bc42-008f-4ae0-8966-c516a59116e8.
2013-06-15 01:11:05 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-3accf6ee-eaeb-450f-85f2-e53c601d11fc
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-140f9da7-f0cf-4c39-b7bf-35f34aca0f87: created successfully
2013-06-15 01:11:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-271eb45d-4c51-4512-90c3-d4c6b731aeca: creating
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-d5331684-9e84-40ec-95ca-dddeb8c08b37: created successfully
2013-06-15 01:11:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-ec76cff5-5272-4580-9187-c7ba28b2ed32: created successfully
2013-06-15 01:11:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:05 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-96865e6d-8641-4de7-987d-44c3a916b7c9
2013-06-15 01:11:05 INFO [cinder.volume.manager] volume volume-ea2de8a0-f89f-4a4c-a763-0a94752c69b0: creating
2013-06-15 01:11:05 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-1332f5d1-bd9a-4669-9e39-1b6e04ee87ef
2013-06-15 01:11:06 INFO [cinder.volume.manager] volume volume-6d7c7b9e-397c-4c57-b789-433678cefd85: created successfully
2013-06-15 01:11:06 INFO [cinder.volume.manager] Clear capabilities
2013-06-15 01:11:06 INFO [cinder.volume.manager] volume volume-876567f6-352d-4aab-8a8a-139afe2a5966: creating
2013-06-15 01:11:06 INFO [cinder.volume.iscsi] Creating iscsi_target for: volume-5e1d7615-5a7f-4d6e-bf39-48e183d15ccd
2013-06-15 01:11:06 INFO [cinder.volume.manager] volume volume-2f5ba4f1-79c8-45b0-bb2e-dc2006625536: created successfully

EXPECTED BEHAVIOR: The volume creation must either error out on all or work successfully for all.

HOW-TO-REPRODUCE:
 Set up OpenStack grizzly environment using Install openstack using https://github.com/mseknibilel/OpenStack-Grizzly-Install-Guide/blob/OVS_MultiNode/OpenStack_Grizzly_Install_Guide.rst

ENVIRONMENT: (Hardware, OS, OS Version, Browser, etc)
 Cinder is deployed in the simplest mode. 1 cinder volume group, no scheduler no volume type feature is utilized.

[Hrushikesh (hrushikesh-gangur)]

I don't think this is duplicate of bug #1191429. These two errors happens at different times and reports different error messages:
- 1191429: This bug indicates create_iscsi_target raise exception.NotFound() NotFound: Resource could not be found.
- 1191431: create_iscsi_target raise exception.ISCSITargetCreateFailed(volume_id=vol_id)

Am not sure whether the cause for both these error messages are same. Please mark duplicate if that is true.

[Hrushikesh (hrushikesh-gangur)]

Seen a similar type of error during bulk volume deletion:

--
2013-06-17 00:38:04 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:04 INFO [cinder.volume.manager] volume volume-a809fde2-625a-4072-b2fe-f0b07e57449e: deleting
2013-06-17 00:38:04 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:04 INFO [cinder.volume.iscsi] Removing iscsi_target for: 1ff3de63-dde5-413e-a26f-b2e6317e6286
2013-06-17 00:38:04 INFO [cinder.volume.iscsi] Removing iscsi_target for: a809fde2-625a-4072-b2fe-f0b07e57449e
2013-06-17 00:38:05 INFO [cinder.volume.manager] volume volume-c5fdf305-489d-4507-a51f-ef7ffa81b0d7: deleting
2013-06-17 00:38:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:05 INFO [cinder.volume.manager] volume volume-cf3d0690-ddff-443d-928e-62794588fee3: deleting
2013-06-17 00:38:05 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:05 INFO [cinder.volume.iscsi] Removing iscsi_target for: c5fdf305-489d-4507-a51f-ef7ffa81b0d7
2013-06-17 00:38:05 INFO [cinder.volume.iscsi] Removing iscsi_target for: cf3d0690-ddff-443d-928e-62794588fee3
2013-06-17 00:38:06 ERROR [cinder.volume.iscsi] Failed to remove iscsi target for volume id:c5fdf305-489d-4507-a51f-ef7ffa81b0d7.
2013-06-17 00:38:12 ERROR [cinder.openstack.common.rpc.amqp] Exception during message handling
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py", line 430, in _process_data
    rval = self.proxy.dispatch(ctxt, version, method, **args)
  File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/dispatcher.py", line 133, in dispatch
    return getattr(proxyobj, method)(ctxt, **kwargs)
  File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 427, in delete_volume
    {'status': 'error_deleting'})
  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/usr/lib/python2.7/dist-packages/cinder/volume/manager.py", line 414, in delete_volume
    self.driver.remove_export(context, volume_ref)
  File "/usr/lib/python2.7/dist-packages/cinder/volume/drivers/lvm.py", line 539, in remove_export
    self.tgtadm.remove_iscsi_target(iscsi_target, 0, volume['id'])
  File "/usr/lib/python2.7/dist-packages/cinder/volume/iscsi.py", line 203, in remove_iscsi_target
    raise exception.ISCSITargetRemoveFailed(volume_id=vol_id)
ISCSITargetRemoveFailed: Failed to remove iscsi target for volume c5fdf305-489d-4507-a51f-ef7ffa81b0d7.
2013-06-17 00:38:13 INFO [cinder.volume.manager] volume volume-e1e5779d-4354-424c-aae4-2a4fef1dd6d7: deleting
2013-06-17 00:38:13 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:13 INFO [cinder.volume.manager] volume volume-c70056fe-d28a-4ca6-9210-7ee6c6e36686: deleting
2013-06-17 00:38:13 INFO [cinder.volume.manager] Clear capabilities
2013-06-17 00:38:13 INFO [cinder.volume.iscsi] Removing iscsi_target for: e1e5779d-4354-424c-aae4-2a4fef1dd6d7
2013-06-17 00:38:13 INFO [cinder.volume.iscsi] Removing iscsi_target for: c70056fe-d28a-4ca6-9210-7ee6c6e36686
2013-06-17 00:38:15 INFO [cinder.volume.manager] volume vo...