<div>Hi,</div><div><br></div><div>I was hoping somebody might be able to help me with an issue I'm having. I have some code I've written to support SolidFire iSCSI devices in san.py. Things work pretty well until I attempt to attach a second volume to an instance running on the compute node.</div>
<div><br></div><div>In other words, I can create an instance, create a volume and attach the created volume. Everything at this point works fine. However, I then create another instance, create another volume and try to attach the second volume to the second instance and I run into issues.</div>
<div><br></div><div>Looking at the logs it appears that the issue is an error from iscsiadm (shown below):</div><div><br></div>(nova.compute.manager): TRACE: Stderr: 'iscsiadm: Could not login to [iface: default, target: iqn.2010-01.com.solidfire:wmit.volume-00000002.51, portal: 192.168.69.211,3260]: \niscsiadm: initiator reported error (15 - already exists)\n'<div>
<br></div><div>A quick check on the compute node to see what it has for entries in /etc/iscsi/nodes, shows that it has created two entries as I would expect:</div><div><br></div><div><div>root@devstack-1:/etc/iscsi# ls /etc/iscsi/nodes/</div>
<div>iqn.2010-01.com.solidfire:wmit.volume-00000001.50</div><div>iqn.2010-01.com.solidfire:wmit.volume-00000002.51</div><div>root@devstack-1:/etc/iscsi# </div><div><br></div><div><div>I'm not sure what the problem is here, is there something that I need to manually configure in my iscsid.conf file to prevent this? Is there possibly something wrong with my export_volume method? I've googled the error message from iscsiadm but not having much luck. </div>
</div><div><br></div><div>Logs are below, does anybody by chance have some experience with this and know what I'm doing wrong?</div><div><br></div><div>Thanks,</div><div>John</div><div><br></div><div><br></div><div><br>
</div><div>~~~~~~~~ nova-compute.log ~~~~~~~~~</div>
<div><br></div><div><div>2011-12-23 10:35:53,579 DEBUG nova.virt.libvirt_conn [-] instance instance-00000002: is running from (pid=1090) spawn /opt/stack/nova/nova/virt/libvirt/connection.py:682</div><div>2011-12-23 10:35:53,580 DEBUG nova.compute.manager [-] Checking state of instance-00000002 from (pid=1090) _get_power_state /opt/stack/nova/nova/compute/manager.py:211</div>
<div>2011-12-23 10:35:54,245 INFO nova.virt.libvirt_conn [-] Instance instance-00000002 spawned successfully.</div><div>2011-12-23 10:36:18,773 DEBUG nova.rpc [-] received {u'_context_roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], u'_context_request_id': u'd4ef443f-6a9d-479a-b76d-87f6f496f28c', u'_context_read_deleted': u'no', u'args': {u'instance_uuid': u'ef91a007-bccc-4b3b-a8dc-ec3fb6c3df0d', u'mountpoint': u'/dev/vdb', u'volume_id': u'2'}, u'_context_auth_token': u'tokentoken', u'_context_strategy': u'keystone', u'_context_is_admin': True, u'_context_project_id': u'1', u'_context_timestamp': u'2011-12-23T18:36:18.661390', u'_context_user_id': u'admin', u'method': u'attach_volume', u'_context_remote_address': u'192.168.68.11'} from (pid=1090) __call__ /opt/stack/nova/nova/rpc/impl_kombu.py:607</div>
<div>2011-12-23 10:36:18,781 DEBUG nova.rpc [-] unpacked context: {'user_id': u'admin', 'roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], 'timestamp': u'2011-12-23T18:36:18.661390', 'auth_token': u'tokentoken', 'msg_id': None, 'remote_address': u'192.168.68.11', 'strategy': u'keystone', 'is_admin': True, 'request_id': u'd4ef443f-6a9d-479a-b76d-87f6f496f28c', 'project_id': u'1', 'read_deleted': u'no'} from (pid=1090) _unpack_context /opt/stack/nova/nova/rpc/impl_kombu.py:653</div>
<div>2011-12-23 10:36:18,782 INFO nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: decorating: |<function attach_volume at 0x26310c8>|</div><div>2011-12-23 10:36:18,783 INFO nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: arguments: |<nova.compute.manager.ComputeManager object at 0x24370d0>| |<nova.rpc.impl_kombu.RpcContext object at 0x40b0450>| |ef91a007-bccc-4b3b-a8dc-ec3fb6c3df0d|</div>
<div>2011-12-23 10:36:18,787 DEBUG nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] instance ef91a007-bccc-4b3b-a8dc-ec3fb6c3df0d: getting locked state from (pid=1090) get_lock /opt/stack/nova/nova/compute/manager.py:1407</div>
<div>2011-12-23 10:36:18,952 INFO nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: locked: |False|</div><div>2011-12-23 10:36:18,952 INFO nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: admin: |True|</div>
<div>2011-12-23 10:36:18,953 INFO nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: executing: |<function attach_volume at 0x26310c8>|</div><div>2011-12-23 10:36:19,068 AUDIT nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] instance ef91a007-bccc-4b3b-a8dc-ec3fb6c3df0d: attaching volume 2 to /dev/vdb</div>
<div>2011-12-23 10:36:19,129 DEBUG nova.rpc [-] Making asynchronous call on volume.devstack-1 ... from (pid=1090) multicall /opt/stack/nova/nova/rpc/impl_kombu.py:737</div><div>2011-12-23 10:36:19,129 DEBUG nova.rpc [-] MSG_ID is 56115d8b6a1a464693c29d8775597b26 from (pid=1090) multicall /opt/stack/nova/nova/rpc/impl_kombu.py:740</div>
<div>2011-12-23 10:36:19,704 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> from (pid=1090) execute /opt/stack/nova/nova/utils.py:201</div>
<div>2011-12-23 10:36:19,764 DEBUG nova.virt.libvirt.volume [-] iscsiadm (): stdout=# BEGIN RECORD 2.0-871</div><div><a href="http://node.name" target="_blank">node.name</a> = iqn.2010-01.com.solidfire:wmit.volume-00000002.51</div>
<div>node.tpgt = -1</div>
<div>node.startup = automatic</div><div>iface.hwaddress = <empty></div><div>iface.ipaddress = <empty></div><div>iface.iscsi_ifacename = default</div><div>iface.net_ifacename = <empty></div><div>iface.transport_name = tcp</div>
<div>iface.initiatorname = <empty></div><div>node.discovery_address = <empty></div><div>node.discovery_port = 0</div><div>node.discovery_type = static</div><div>node.session.initial_cmdsn = 0</div><div>node.session.initial_login_retry_max = 8</div>
<div>node.session.xmit_thread_priority = -20</div><div>node.session.cmds_max = 128</div><div>node.session.queue_depth = 32</div><div>node.session.auth.authmethod = CHAP</div><div>node.session.auth.username = devstack-1-1</div>
<div>node.session.auth.password = ********</div><div>node.session.auth.username_in = <empty></div><div>node.session.auth.password_in = <empty></div><div>node.session.timeo.replacement_timeout = 120</div><div>
node.session.err_timeo.abort_timeout = 15</div>
<div>node.session.err_timeo.lu_reset_timeout = 20</div><div>node.session.err_timeo.host_reset_timeout = 60</div><div>node.session.iscsi.FastAbort = Yes</div><div>node.session.iscsi.InitialR2T = No</div><div>node.session.iscsi.ImmediateData = Yes</div>
<div>node.session.iscsi.FirstBurstLength = 262144</div><div>node.session.iscsi.MaxBurstLength = 16776192</div><div>node.session.iscsi.DefaultTime2Retain = 0</div><div>node.session.iscsi.DefaultTime2Wait = 2</div><div>node.session.iscsi.MaxConnections = 1</div>
<div>node.session.iscsi.MaxOutstandingR2T = 1</div><div>node.session.iscsi.ERL = 0</div><div>node.conn[0].address = 192.168.69.211</div><div>node.conn[0].port = 3260</div><div>node.conn[0].startup = manual</div><div>node.conn[0].tcp.window_size = 524288</div>
<div>node.conn[0].tcp.type_of_service = 0</div><div>node.conn[0].timeo.logout_timeout = 15</div><div>node.conn[0].timeo.login_timeout = 15</div><div>node.conn[0].timeo.auth_timeout = 45</div><div>node.conn[0].timeo.noop_out_interval = 5</div>
<div>node.conn[0].timeo.noop_out_timeout = 5</div><div>node.conn[0].iscsi.MaxRecvDataSegmentLength = 262144</div><div>node.conn[0].iscsi.HeaderDigest = None</div><div>node.conn[0].iscsi.DataDigest = None</div><div>node.conn[0].iscsi.IFMarker = No</div>
<div>node.conn[0].iscsi.OFMarker = No</div><div># END RECORD</div><div> stderr= from (pid=1090) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:98</div><div>2011-12-23 10:36:19,766 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> --op update -n node.session.auth.authmethod -v CHAP from (pid=1090) execute /opt/stack/nova/nova/utils.py:201</div>
<div>2011-12-23 10:36:19,791 DEBUG nova.virt.libvirt.volume [-] iscsiadm ('--op', 'update', '-n', 'node.session.auth.authmethod', '-v', u'CHAP'): stdout= stderr= from (pid=1090) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:98</div>
<div>2011-12-23 10:36:19,792 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> --op update -n node.session.auth.username -v devstack-1-1 from (pid=1090) execute /opt/stack/nova/nova/utils.py:201</div>
<div>2011-12-23 10:36:19,817 DEBUG nova.virt.libvirt.volume [-] iscsiadm ('--op', 'update', '-n', 'node.session.auth.username', '-v', u'devstack-1-1'): stdout= stderr= from (pid=1090) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:98</div>
<div>2011-12-23 10:36:19,819 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> --op update -n node.session.auth.password -v DOMB9W14FK8R from (pid=1090) execute /opt/stack/nova/nova/utils.py:201</div>
<div>2011-12-23 10:36:19,838 DEBUG nova.virt.libvirt.volume [-] iscsiadm ('--op', 'update', '-n', 'node.session.auth.password', '-v', u'DOMB9W14FK8R'): stdout= stderr= from (pid=1090) _run_iscsiadm /opt/stack/nova/nova/virt/libvirt/volume.py:98</div>
<div>2011-12-23 10:36:19,843 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> --login from (pid=1090) execute /opt/stack/nova/nova/utils.py:201</div>
<div>2011-12-23 10:36:19,855 DEBUG nova.utils [-] Result was 255 from (pid=1090) execute /opt/stack/nova/nova/utils.py:217</div><div>2011-12-23 10:36:19,856 ERROR nova.compute.manager [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] instance ef91a007-bccc-4b3b-a8dc-ec3fb6c3df0d: attach failed /dev/vdb, removing</div>
<div>(nova.compute.manager): TRACE: Traceback (most recent call last):</div><div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line 1510, in attach_volume</div><div>(nova.compute.manager): TRACE: mountpoint)</div>
<div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/exception.py", line 115, in wrapped</div><div>(nova.compute.manager): TRACE: return f(*args, **kw)</div><div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/virt/libvirt/connection.py", line 427, in attach_volume</div>
<div>(nova.compute.manager): TRACE: mount_device)</div><div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/virt/libvirt/connection.py", line 419, in volume_driver_method</div><div>(nova.compute.manager): TRACE: return method(connection_info, *args, **kwargs)</div>
<div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/virt/libvirt/volume.py", line 128, in connect_volume</div><div>(nova.compute.manager): TRACE: self._run_iscsiadm(iscsi_properties, ("--login",))</div>
<div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/virt/libvirt/volume.py", line 96, in _run_iscsiadm</div><div>(nova.compute.manager): TRACE: check_exit_code=check_exit_code)</div><div>(nova.compute.manager): TRACE: File "/opt/stack/nova/nova/utils.py", line 225, in execute</div>
<div>(nova.compute.manager): TRACE: cmd=' '.join(cmd))</div><div>(nova.compute.manager): TRACE: ProcessExecutionError: Unexpected error while running command.</div><div>(nova.compute.manager): TRACE: Command: sudo iscsiadm -m node -T iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p <a href="http://192.168.69.211:3260" target="_blank">192.168.69.211:3260</a> --login</div>
<div>(nova.compute.manager): TRACE: Exit code: 255</div><div>(nova.compute.manager): TRACE: Stdout: 'Logging in to [iface: default, target: iqn.2010-01.com.solidfire:wmit.volume-00000002.51, portal: 192.168.69.211,3260]\n'</div>
<div>(nova.compute.manager): TRACE: Stderr: 'iscsiadm: Could not login to [iface: default, target: iqn.2010-01.com.solidfire:wmit.volume-00000002.51, portal: 192.168.69.211,3260]: \niscsiadm: initiator reported error (15 - already exists)\n'</div>
<div>(nova.compute.manager): TRACE: </div><div>2011-12-23 10:36:19,888 DEBUG nova.rpc [-] Making asynchronous call on volume.devstack-1 ... from (pid=1090) multicall /opt/stack/nova/nova/rpc/impl_kombu.py:737</div><div>2011-12-23 10:36:19,888 DEBUG nova.rpc [-] MSG_ID is 86f9dbb136324b5394a209ab68dbf0af from (pid=1090) multicall /opt/stack/nova/nova/rpc/impl_kombu.py:740</div>
<div>2011-12-23 10:36:20,064 ERROR nova.rpc [-] Exception during message handling</div><div>(nova.rpc): TRACE: Traceback (most recent call last):</div><div>(nova.rpc): TRACE: File "/opt/stack/nova/nova/rpc/impl_kombu.py", line 627, in _process_data</div>
<div>(nova.rpc): TRACE: rval = node_func(context=ctxt, **node_args)</div><div>(nova.rpc): TRACE: File "/opt/stack/nova/nova/exception.py", line 115, in wrapped</div><div>(nova.rpc): TRACE: return f(*args, **kw)</div>
<div>(nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line 115, in decorated_function</div><div>(nova.rpc): TRACE: function(self, context, instance_uuid, *args, **kwargs)</div><div>(nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line 138, in decorated_function</div>
<div>(nova.rpc): TRACE: self.add_instance_fault_from_exc(context, instance_uuid, e)</div><div>(nova.rpc): TRACE: File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__</div><div>(nova.rpc): TRACE: self.gen.next()</div>
<div>(nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line 133, in decorated_function</div><div>(nova.rpc): TRACE: return function(self, context, instance_uuid, *args, **kwargs)</div><div>
(nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line 1519, in attach_volume</div><div>(nova.rpc): TRACE: raise exc</div><div>(nova.rpc): TRACE: ProcessExecutionError: Unexpected error while running command.</div>
<div>(nova.rpc): TRACE: Command: None</div><div>(nova.rpc): TRACE: Exit code: -</div><div>(nova.rpc): TRACE: Stdout: None</div><div>(nova.rpc): TRACE: Stderr: None</div><div>(nova.rpc): TRACE: </div></div><div><br></div>
</div>
<div><br></div><div><br></div><div><br></div><div>~~~~ nova-volume.log~~~~~~~~~~~</div><div><br></div><div><div>2011-12-23 10:54:12,481 DEBUG nova.rpc [-] received {u'_context_roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], u'_msg_id': u'd3203d11b49b4ab28b5a15b13126093b', u'_context_read_deleted': u'no', u'_context_request_id': u'90be39e2-b970-4954-afb3-83dd054bc02a', u'args': {u'volume_id': u'2', u'address': u'192.168.68.11'}, u'_context_auth_token': u'tokentoken', u'_context_strategy': u'keystone', u'_context_is_admin': True, u'_context_project_id': u'1', u'_context_timestamp': u'2011-12-23T18:54:11.923697', u'_context_user_id': u'admin', u'method': u'initialize_connection', u'_context_remote_address': u'192.168.68.11'} from (pid=1112) __call__ /opt/stack/nova/nova/rpc/impl_kombu.py:607</div>
<div>2011-12-23 10:54:12,482 DEBUG nova.rpc [-] unpacked context: {'user_id': u'admin', 'roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], 'timestamp': u'2011-12-23T18:54:11.923697', 'auth_token': u'tokentoken', 'msg_id': u'd3203d11b49b4ab28b5a15b13126093b', 'remote_address': u'192.168.68.11', 'strategy': u'keystone', 'is_admin': True, 'request_id': u'90be39e2-b970-4954-afb3-83dd054bc02a', 'project_id': u'1', 'read_deleted': u'no'} from (pid=1112) _unpack_context /opt/stack/nova/nova/rpc/impl_kombu.py:653</div>
<div>2011-12-23 10:54:13,088 DEBUG nova.rpc [-] received {u'_context_roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], u'_msg_id': u'6ba61e4083204d55bcf3762cd68b34a6', u'_context_read_deleted': u'no', u'_context_request_id': u'90be39e2-b970-4954-afb3-83dd054bc02a', u'args': {u'volume_id': u'2', u'address': u'192.168.68.11'}, u'_context_auth_token': u'tokentoken', u'_context_strategy': u'keystone', u'_context_is_admin': True, u'_context_project_id': u'1', u'_context_timestamp': u'2011-12-23T18:54:11.923697', u'_context_user_id': u'admin', u'method': u'terminate_connection', u'_context_remote_address': u'192.168.68.11'} from (pid=1112) __call__ /opt/stack/nova/nova/rpc/impl_kombu.py:607</div>
<div>2011-12-23 10:54:13,088 DEBUG nova.rpc [-] unpacked context: {'user_id': u'admin', 'roles': [u'Admin', u'Admin', u'KeystoneAdmin', u'KeystoneServiceAdmin'], 'timestamp': u'2011-12-23T18:54:11.923697', 'auth_token': u'tokentoken', 'msg_id': u'6ba61e4083204d55bcf3762cd68b34a6', 'remote_address': u'192.168.68.11', 'strategy': u'keystone', 'is_admin': True, 'request_id': u'90be39e2-b970-4954-afb3-83dd054bc02a', 'project_id': u'1', 'read_deleted': u'no'} from (pid=1112) _unpack_context /opt/stack/nova/nova/rpc/impl_kombu.py:653</div>
<div>2011-12-23 10:54:30,152 DEBUG nova.manager [03fbf039-8c6b-4515-a800-a202bc105337 None None] Running periodic task VolumeManager._publish_service_capabilities from (pid=1112) periodic_tasks /opt/stack/nova/nova/manager.py:152</div>
<div>2011-12-23 10:54:30,152 DEBUG nova.manager [03fbf039-8c6b-4515-a800-a202bc105337 None None] Running periodic task VolumeManager._report_driver_status from (pid=1112) periodic_tasks /opt/stack/nova/nova/manager.py:152</div>
</div><div><br></div>