Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

launch VM from image with volume creation on Equalogic

Hallo

I set up a multi node openstack system. Controller 10.0.0.11, neutron 10.0.0.21, compute1 10.0.0.31, compute2 10.0.0.32, block1 10.0.041 I can create and work with new instances until I try to create or attach them volumes. I connect already (block1 node) a Dell Equalogic storage system, which is working well and I can create volumes.

As you see in the log file the problem is that after the correct volume creation the with the name: disk-8894b59c-d792-4724-9675-89dc64a3a621 the system tries to attach the volume: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0 to the new instance. As you see one CHAR, the last one from the volume name is missing and of course the action fails.

I cannot find any configuration error and believe that the Equallogic driver works properly.

Any idea why it happens ??

Thanks in advance

2014-05-07 15:10:41.353 6674 INFO cinder.volume.drivers.eqlx [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] EQL-driver: executing "pool select default show" 2014-05-07 15:10:41.354 6674 INFO paramiko.transport [-] Secsh channel 6 opened. 2014-05-07 15:10:41.761 6674 INFO oslo.messaging._drivers.impl_qpid [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672 2014-05-07 15:10:41.776 6674 INFO oslo.messaging._drivers.impl_qpid [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672 2014-05-07 15:11:01.826 6674 INFO cinder.volume.manager [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] Updating volume status 2014-05-07 15:11:01.827 6674 INFO cinder.volume.drivers.eqlx [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] EQL-driver: executing "pool select default show" 2014-05-07 15:11:01.829 6674 INFO paramiko.transport [-] Secsh channel 7 opened. 2014-05-07 15:12:01.837 6674 INFO cinder.volume.manager [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] Updating volume status 2014-05-07 15:12:01.837 6674 INFO cinder.volume.drivers.eqlx [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] EQL-driver: executing "pool select default show" 2014-05-07 15:12:01.839 6674 INFO paramiko.transport [-] Secsh channel 8 opened. 2014-05-07 15:12:18.298 6668 INFO cinder.openstack.common.service [-] Caught SIGTERM, stopping children 2014-05-07 15:12:18.298 6668 INFO cinder.openstack.common.service [-] Waiting on 1 children to exit 2014-05-07 15:12:18.298 6674 INFO cinder.openstack.common.service [-] Caught SIGTERM, exiting 2014-05-07 15:12:18.302 6668 INFO cinder.openstack.common.service [-] Child 6674 exited with status 1 2014-05-07 15:12:18.771 6692 INFO cinder.openstack.common.service [-] Starting 1 workers 2014-05-07 15:12:18.773 6692 INFO cinder.openstack.common.service [-] Started child 6698 2014-05-07 15:12:18.776 6698 AUDIT cinder.service [-] Starting cinder-volume node (version 2014.1) 2014-05-07 15:12:18.777 6698 INFO cinder.volume.manager [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Starting volume driver DellEQLSanISCSIDriver (1.0.0) 2014-05-07 15:12:19.131 6698 INFO paramiko.transport [-] Connected (version 1.99, client OpenSSH_3.4) 2014-05-07 15:12:19.639 6698 INFO paramiko.transport [-] Authentication (password) successful! 2014-05-07 15:12:19.640 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings confirmation off" 2014-05-07 15:12:19.641 6698 INFO paramiko.transport [-] Secsh channel 1 opened. 2014-05-07 15:12:19.841 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings paging off" 2014-05-07 15:12:19.882 6698 INFO paramiko.transport [-] Secsh channel 2 opened. 2014-05-07 15:12:20.108 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings events off" 2014-05-07 15:12:20.150 6698 INFO paramiko.transport [-] Secsh channel 3 opened. 2014-05-07 15:12:20.375 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings formatoutput off" 2014-05-07 15:12:20.418 6698 INFO paramiko.transport [-] Secsh channel 4 opened. 2014-05-07 15:12:20.641 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "grpparams show" 2014-05-07 15:12:20.682 6698 INFO paramiko.transport [-] Secsh channel 5 opened. 2014-05-07 15:12:20.982 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: Setup is complete, group IP is 192.168.130.186 2014-05-07 15:12:21.214 6698 INFO cinder.volume.manager [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Updating volume status 2014-05-07 15:12:21.214 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "pool select default show" 2014-05-07 15:12:21.216 6698 INFO paramiko.transport [-] Secsh channel 6 opened. 2014-05-07 15:12:21.642 6698 INFO oslo.messaging._drivers.impl_qpid [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672 2014-05-07 15:12:21.656 6698 INFO oslo.messaging._drivers.impl_qpid [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672 2014-05-07 15:13:11.707 6698 INFO cinder.volume.manager [req-c65e4d6d-d474-4703-9df7-29dfc682359e - - - - -] Updating volume status 2014-05-07 15:13:11.707 6698 INFO cinder.volume.drivers.eqlx [req-c65e4d6d-d474-4703-9df7-29dfc682359e - - - - -] EQL-driver: executing "pool select default show" 2014-05-07 15:13:11.709 6698 INFO paramiko.transport [-] Secsh channel 7 opened. 2014-05-07 15:14:11.703 6698 INFO cinder.volume.manager [-] Updating volume status 2014-05-07 15:14:11.704 6698 INFO cinder.volume.drivers.eqlx [-] EQL-driver: executing "pool select default show" 2014-05-07 15:14:11.705 6698 INFO paramiko.transport [-] Secsh channel 8 opened. 2014-05-07 15:14:40.462 6698 WARNING cinder.context [-] Arguments dropped when creating context: {'user': u'192760ddd6c5486ca106db0a794f304b', 'tenant': u'5790e757c92a4de5b2ec8a5fc7ea21ef', 'user_identity': u'192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -'} 2014-05-07 15:14:40.570 6698 INFO cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Volume 8894b59c-d792-4724-9675-89dc64a3a621: being created using CreateVolumeFromSpecTask._create_from_image with specification: {'status': u'creating', 'image_location': (None, None), 'volume_size': 20, 'volume_name': u'disk-8894b59c-d792-4724-9675-89dc64a3a621', 'image_id': u'987efb7e-ddd5-4422-b97c-317454c8b33f', 'image_service': <cinder.image.glance.glanceimageservice object="" at="" 0x48f9ed0="">, 'image_meta': {'status': u'active', 'name': u'Centos_Live_CD6.5', 'deleted': False, 'container_format': u'bare', 'created_at': datetime.datetime(2014, 4, 26, 20, 56, 5, tzinfo=<iso8601.iso8601.utc object="" at="" 0x49cdf90="">), 'disk_format': u'iso', 'updated_at': datetime.datetime(2014, 4, 26, 20, 58, tzinfo=<iso8601.iso8601.utc object="" at="" 0x49cdf90="">), 'id': u'987efb7e-ddd5-4422-b97c-317454c8b33f', 'owner': u'034547bfda50445ab1d82cc660bb083d', 'min_ram': 0, 'checksum': u'8c37390fa5d932d03feb05fba13fe92e', 'min_disk': 0, 'is_public': True, 'deleted_at': None, 'properties': {}, 'size': 680525824}} 2014-05-07 15:14:40.571 6698 INFO cinder.volume.drivers.eqlx [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] EQL-driver: executing "volume create disk-8894b59c-d792-4724-9675-89dc64a3a621 20G thin-provision" 2014-05-07 15:14:40.573 6698 INFO paramiko.transport [-] Secsh channel 9 opened. 2014-05-07 15:14:41.069 6698 INFO cinder.volume.drivers.eqlx [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] EQL-driver: executing "volume select disk-8894b59c-d792-4724-9675-89dc64a3a621 access create initiator iqn.1994-05.com.redhat:3d3794f493d6" 2014-05-07 15:14:41.071 6698 INFO paramiko.transport [-] Secsh channel 10 opened. 2014-05-07 15:14:42.146 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. Will rescan & retry. Try number: 0 2014-05-07 15:14:43.203 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. Will rescan & retry. Try number: 1 2014-05-07 15:14:47.259 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. Will rescan & retry. Try number: 2 2014-05-07 15:14:56.316 6698 ERROR cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Failed to copy image 987efb7e-ddd5-4422-b97c-317454c8b33f to volume: 8894b59c-d792-4724-9675-89dc64a3a621, error: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. 2014-05-07 15:14:56.356 6698 ERROR cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Volume 8894b59c-d792-4724-9675-89dc64a3a621: create failed 2014-05-07 15:14:56.357 6698 ERROR oslo.messaging.rpc.dispatcher [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Exception during message handling: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last): 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher incoming.message)) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, new_args) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 363, in create_volume 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher _run_flow() 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 356, in _run_flow 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher flow_engine.run() 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/utils/lock_utils.py", line 51, in wrapper 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher return f(args, *kwargs) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 118, in run 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher self._run() 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 128, in _run 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher self._revert(misc.Failure()) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 81, in _revert 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher misc.Failure.reraise_if_any(failures.values()) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 487, in reraise_if_any 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher failures[0].reraise() 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 494, in reraise 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher six.reraise(self._exc_info) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/executor.py", line 36, in _execute_task 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher result = task.execute(arguments) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 594, in execute 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher volume_spec) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 556, in _create_from_image 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher image_id, image_location, image_service) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 470, in _copy_image_to_volume 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher raise exception.ImageCopyFailure(reason=ex) 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher ImageCopyFailure: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. 2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher 2014-05-07 15:14:56.359 6698 ERROR oslo.messaging._drivers.common [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Returning exception Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. to caller 2014-05-07 15:14:56.360 6698 ERROR oslo.messaging._drivers.common [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n incoming.message))\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n return self._do_dispatch(endpoint, method, ctxt, args)\n', ' File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n result = getattr(endpoint, method)(ctxt, *new_args)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 363, in create_volume\n _run_flow()\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 356, in _run_flow\n flow_engine.run()\n', ' File "/usr/lib/python2.6/site-packages/taskflow/utils/lock_utils.py", line 51, in wrapper\n return f(args, *kwargs)\n', ' File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 118, in run\n self._run()\n', ' File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 128, in _run\n self._revert(misc.Failure())\n', ' File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 81, in _revert\n misc.Failure.reraise_if_any(failures.values())\n', ' File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 487, in reraise_if_any\n failures[0].reraise()\n', ' File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 494, in reraise\n six.reraise(self._exc_info)\n', ' File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/executor.py", line 36, in _execute_task\n result = task.execute(arguments)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 594, in execute\n *volume_spec)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 556, in _create_from_image\n image_id, image_location, image_service)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 470, in _copy_image_to_volume\n raise exception.ImageCopyFailure(reason=ex)\n', 'ImageCopyFailure: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0.\n'] 2014-05-07 15:15:11.706 6698 INFO cinder.volume.manager [-] Updating volume status 2014-05-07 15:15:11.707 6698 INFO cinder.volume.drivers.eqlx [-] EQL-driver: executing "pool select default show" 2014-05-07 15:15:11.709 6698 INFO paramiko.transport [-] Secsh channel 11 opened.

launch VM from image with volume creation on Equalogic

Hallo

I set up a multi node openstack system. Controller 10.0.0.11, neutron 10.0.0.21, compute1 10.0.0.31, compute2 10.0.0.32, block1 10.0.041 I can create and work with new instances until I try to create or attach them volumes. I connect already (block1 node) a Dell Equalogic storage system, which is working well and I can create volumes.

As you see in the log file the problem is that after the correct volume creation the with the name: disk-8894b59c-d792-4724-9675-89dc64a3a621 name: disk-8894b59c-d792-4724-9675-89dc64a3a621 the system tries to attach the volume: volume:

 /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0

to the new instance. instance.

As you see one CHAR, the last one from the volume name is missing and of course the action fails.

fails. I cannot find any configuration error and believe that the Equallogic driver works properly.

Any idea why it happens ??

Thanks in advance

2014-05-07 15:10:41.353 6674 INFO cinder.volume.drivers.eqlx [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] EQL-driver: executing "pool select default show"
2014-05-07 15:10:41.354 6674 INFO paramiko.transport [-] Secsh channel 6 opened.
2014-05-07 15:10:41.761 6674 INFO oslo.messaging._drivers.impl_qpid [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672
2014-05-07 15:10:41.776 6674 INFO oslo.messaging._drivers.impl_qpid [req-bf833640-12ba-41b7-a303-7f8132334028 - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672
2014-05-07 15:11:01.826 6674 INFO cinder.volume.manager [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] Updating volume status
2014-05-07 15:11:01.827 6674 INFO cinder.volume.drivers.eqlx [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] EQL-driver: executing "pool select default show"
2014-05-07 15:11:01.829 6674 INFO paramiko.transport [-] Secsh channel 7 opened.
2014-05-07 15:12:01.837 6674 INFO cinder.volume.manager [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] Updating volume status
2014-05-07 15:12:01.837 6674 INFO cinder.volume.drivers.eqlx [req-77c7554e-49b4-456b-9ef9-45b08eb2cc93 - - - - -] EQL-driver: executing "pool select default show"
2014-05-07 15:12:01.839 6674 INFO paramiko.transport [-] Secsh channel 8 opened.
2014-05-07 15:12:18.298 6668 INFO cinder.openstack.common.service [-] Caught SIGTERM, stopping children
2014-05-07 15:12:18.298 6668 INFO cinder.openstack.common.service [-] Waiting on 1 children to exit
2014-05-07 15:12:18.298 6674 INFO cinder.openstack.common.service [-] Caught SIGTERM, exiting
2014-05-07 15:12:18.302 6668 INFO cinder.openstack.common.service [-] Child 6674 exited with status 1
2014-05-07 15:12:18.771 6692 INFO cinder.openstack.common.service [-] Starting 1 workers
2014-05-07 15:12:18.773 6692 INFO cinder.openstack.common.service [-] Started child 6698
2014-05-07 15:12:18.776 6698 AUDIT cinder.service [-] Starting cinder-volume node (version 2014.1)
2014-05-07 15:12:18.777 6698 INFO cinder.volume.manager [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Starting volume driver DellEQLSanISCSIDriver (1.0.0)
2014-05-07 15:12:19.131 6698 INFO paramiko.transport [-] Connected (version 1.99, client OpenSSH_3.4)
2014-05-07 15:12:19.639 6698 INFO paramiko.transport [-] Authentication (password) successful!
2014-05-07 15:12:19.640 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings confirmation off"
2014-05-07 15:12:19.641 6698 INFO paramiko.transport [-] Secsh channel 1 opened.
2014-05-07 15:12:19.841 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings paging off"
2014-05-07 15:12:19.882 6698 INFO paramiko.transport [-] Secsh channel 2 opened.
2014-05-07 15:12:20.108 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings events off"
2014-05-07 15:12:20.150 6698 INFO paramiko.transport [-] Secsh channel 3 opened.
2014-05-07 15:12:20.375 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "cli-settings formatoutput off"
2014-05-07 15:12:20.418 6698 INFO paramiko.transport [-] Secsh channel 4 opened.
2014-05-07 15:12:20.641 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "grpparams show"
2014-05-07 15:12:20.682 6698 INFO paramiko.transport [-] Secsh channel 5 opened.
2014-05-07 15:12:20.982 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: Setup is complete, group IP is 192.168.130.186
2014-05-07 15:12:21.214 6698 INFO cinder.volume.manager [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Updating volume status
2014-05-07 15:12:21.214 6698 INFO cinder.volume.drivers.eqlx [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] EQL-driver: executing "pool select default show"
2014-05-07 15:12:21.216 6698 INFO paramiko.transport [-] Secsh channel 6 opened.
2014-05-07 15:12:21.642 6698 INFO oslo.messaging._drivers.impl_qpid [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672
2014-05-07 15:12:21.656 6698 INFO oslo.messaging._drivers.impl_qpid [req-71090868-6280-4e41-b022-9e9aeabf312b - - - - -] Connected to AMQP server on controller1.ipxgate.com:5672
2014-05-07 15:13:11.707 6698 INFO cinder.volume.manager [req-c65e4d6d-d474-4703-9df7-29dfc682359e - - - - -] Updating volume status
2014-05-07 15:13:11.707 6698 INFO cinder.volume.drivers.eqlx [req-c65e4d6d-d474-4703-9df7-29dfc682359e - - - - -] EQL-driver: executing "pool select default show"
2014-05-07 15:13:11.709 6698 INFO paramiko.transport [-] Secsh channel 7 opened.
2014-05-07 15:14:11.703 6698 INFO cinder.volume.manager [-] Updating volume status
2014-05-07 15:14:11.704 6698 INFO cinder.volume.drivers.eqlx [-] EQL-driver: executing "pool select default show"
2014-05-07 15:14:11.705 6698 INFO paramiko.transport [-] Secsh channel 8 opened.
2014-05-07 15:14:40.462 6698 WARNING cinder.context [-] Arguments dropped when creating context: {'user': u'192760ddd6c5486ca106db0a794f304b', 'tenant': u'5790e757c92a4de5b2ec8a5fc7ea21ef', 'user_identity': u'192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -'}
2014-05-07 15:14:40.570 6698 INFO cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Volume 8894b59c-d792-4724-9675-89dc64a3a621: being created using CreateVolumeFromSpecTask._create_from_image with specification: {'status': u'creating', 'image_location': (None, None), 'volume_size': 20, 'volume_name': u'disk-8894b59c-d792-4724-9675-89dc64a3a621', 'image_id': u'987efb7e-ddd5-4422-b97c-317454c8b33f', 'image_service': <cinder.image.glance.glanceimageservice object="" at="" 0x48f9ed0="">, <cinder.image.glance.GlanceImageService object at 0x48f9ed0>, 'image_meta': {'status': u'active', 'name': u'Centos_Live_CD6.5', 'deleted': False, 'container_format': u'bare', 'created_at': datetime.datetime(2014, 4, 26, 20, 56, 5, tzinfo=<iso8601.iso8601.utc object="" at="" 0x49cdf90="">), tzinfo=<iso8601.iso8601.Utc object at 0x49cdf90>), 'disk_format': u'iso', 'updated_at': datetime.datetime(2014, 4, 26, 20, 58, tzinfo=<iso8601.iso8601.utc object="" at="" 0x49cdf90="">), tzinfo=<iso8601.iso8601.Utc object at 0x49cdf90>), 'id': u'987efb7e-ddd5-4422-b97c-317454c8b33f', 'owner': u'034547bfda50445ab1d82cc660bb083d', 'min_ram': 0, 'checksum': u'8c37390fa5d932d03feb05fba13fe92e', 'min_disk': 0, 'is_public': True, 'deleted_at': None, 'properties': {}, 'size': 680525824}}
2014-05-07 15:14:40.571 6698 INFO cinder.volume.drivers.eqlx [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] EQL-driver: executing "volume create disk-8894b59c-d792-4724-9675-89dc64a3a621 20G thin-provision"
2014-05-07 15:14:40.573 6698 INFO paramiko.transport [-] Secsh channel 9 opened.
2014-05-07 15:14:41.069 6698 INFO cinder.volume.drivers.eqlx [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] EQL-driver: executing "volume select disk-8894b59c-d792-4724-9675-89dc64a3a621 **disk-8894b59c-d792-4724-9675-89dc64a3a621** access create initiator iqn.1994-05.com.redhat:3d3794f493d6"
2014-05-07 15:14:41.071 6698 INFO paramiko.transport [-] Secsh channel 10 opened.
2014-05-07 15:14:42.146 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. **/dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0**. Will rescan & retry.  Try number: 0
2014-05-07 15:14:43.203 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. Will rescan & retry.  Try number: 1
2014-05-07 15:14:47.259 6698 WARNING cinder.brick.initiator.connector [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ISCSI volume not yet found at: /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. Will rescan & retry.  Try number: 2
2014-05-07 15:14:56.316 6698 ERROR cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Failed to copy image 987efb7e-ddd5-4422-b97c-317454c8b33f to volume: 8894b59c-d792-4724-9675-89dc64a3a621, error: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0.
2014-05-07 15:14:56.356 6698 ERROR cinder.volume.flows.manager.create_volume [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Volume 8894b59c-d792-4724-9675-89dc64a3a621: create failed
2014-05-07 15:14:56.357 6698 ERROR oslo.messaging.rpc.dispatcher [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Exception during message handling: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0.
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, new_args)
**new_args)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 363, in create_volume
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     _run_flow()
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 356, in _run_flow
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     flow_engine.run()
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/utils/lock_utils.py", line 51, in wrapper
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     return f(args, *kwargs)
f(*args, **kwargs)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 118, in run
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     self._run()
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 128, in _run
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     self._revert(misc.Failure())
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 81, in _revert
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     misc.Failure.reraise_if_any(failures.values())
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 487, in reraise_if_any
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     failures[0].reraise()
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 494, in reraise
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self._exc_info)
six.reraise(*self._exc_info)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/executor.py", line 36, in _execute_task
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     result = task.execute(arguments)
task.execute(**arguments)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 594, in execute
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     volume_spec)
**volume_spec)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 556, in _create_from_image
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     image_id, image_location, image_service)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher   File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 470, in _copy_image_to_volume
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher     raise exception.ImageCopyFailure(reason=ex)
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher ImageCopyFailure: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0.
2014-05-07 15:14:56.357 6698 TRACE oslo.messaging.rpc.dispatcher
2014-05-07 15:14:56.359 6698 ERROR oslo.messaging._drivers.common [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] Returning exception Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0. to caller
2014-05-07 15:14:56.360 6698 ERROR oslo.messaging._drivers.common [req-b2635d99-7e60-4ecd-8a60-27cb70f53809 192760ddd6c5486ca106db0a794f304b 5790e757c92a4de5b2ec8a5fc7ea21ef - - -] ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/usr/lib/python2.6/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, *new_args)\n', **new_args)\n', '  File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 363, in create_volume\n    _run_flow()\n', '  File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 356, in _run_flow\n    flow_engine.run()\n', '  File "/usr/lib/python2.6/site-packages/taskflow/utils/lock_utils.py", line 51, in wrapper\n    return f(args, *kwargs)\n', f(*args, **kwargs)\n', '  File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 118, in run\n    self._run()\n', '  File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 128, in _run\n    self._revert(misc.Failure())\n', '  File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/engine.py", line 81, in _revert\n    misc.Failure.reraise_if_any(failures.values())\n', '  File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 487, in reraise_if_any\n    failures[0].reraise()\n', '  File "/usr/lib/python2.6/site-packages/taskflow/utils/misc.py", line 494, in reraise\n    six.reraise(self._exc_info)\n', six.reraise(*self._exc_info)\n', '  File "/usr/lib/python2.6/site-packages/taskflow/engines/action_engine/executor.py", line 36, in _execute_task\n    result = task.execute(arguments)\n', task.execute(**arguments)\n', '  File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 594, in execute\n    *volume_spec)\n', **volume_spec)\n', '  File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 556, in _create_from_image\n    image_id, image_location, image_service)\n', '  File "/usr/lib/python2.6/site-packages/cinder/volume/flows/manager/create_volume.py", line 470, in _copy_image_to_volume\n    raise exception.ImageCopyFailure(reason=ex)\n', 'ImageCopyFailure: Failed to copy image to volume: Volume device not found at /dev/disk/by-path/ip-192.168.130.186:3260-iscsi-iqn.2001-05.com.equallogic:0-8a0906-1769c3806-55100000145536a3-disk-8894b59c-d792-4724-9675-89dc64a3a62-lun-0.\n']
2014-05-07 15:15:11.706 6698 INFO cinder.volume.manager [-] Updating volume status
2014-05-07 15:15:11.707 6698 INFO cinder.volume.drivers.eqlx [-] EQL-driver: executing "pool select default show"
2014-05-07 15:15:11.709 6698 INFO paramiko.transport [-] Secsh channel 11 opened.

opened.