Additional info... It turns out that restarting open-iscsi resolves the problem. I'm still curious as to what causes it to get into this state to begin with however.
Thanks, John On Fri, Dec 23, 2011 at 12:06 PM, John Griffith <[email protected] > wrote: > Hi, > > 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. > > 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. > > Looking at the logs it appears that the issue is an error from iscsiadm > (shown below): > > (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' > > 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: > > root@devstack-1:/etc/iscsi# ls /etc/iscsi/nodes/ > iqn.2010-01.com.solidfire:wmit.volume-00000001.50 > iqn.2010-01.com.solidfire:wmit.volume-00000002.51 > root@devstack-1:/etc/iscsi# > > 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. > > Logs are below, does anybody by chance have some experience with this and > know what I'm doing wrong? > > Thanks, > John > > > > ~~~~~~~~ nova-compute.log ~~~~~~~~~ > > 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 > 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 > 2011-12-23 10:35:54,245 INFO nova.virt.libvirt_conn [-] Instance > instance-00000002 spawned successfully. > 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 > 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 > 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>| > 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| > 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 > 2011-12-23 10:36:18,952 INFO nova.compute.manager > [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: locked: > |False| > 2011-12-23 10:36:18,952 INFO nova.compute.manager > [d4ef443f-6a9d-479a-b76d-87f6f496f28c admin 1] check_instance_lock: admin: > |True| > 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>| > 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 > 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 > 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 > 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 192.168.69.211:3260 from (pid=1090) execute > /opt/stack/nova/nova/utils.py:201 > 2011-12-23 10:36:19,764 DEBUG nova.virt.libvirt.volume [-] iscsiadm (): > stdout=# BEGIN RECORD 2.0-871 > node.name = iqn.2010-01.com.solidfire:wmit.volume-00000002.51 > node.tpgt = -1 > node.startup = automatic > iface.hwaddress = <empty> > iface.ipaddress = <empty> > iface.iscsi_ifacename = default > iface.net_ifacename = <empty> > iface.transport_name = tcp > iface.initiatorname = <empty> > node.discovery_address = <empty> > node.discovery_port = 0 > node.discovery_type = static > node.session.initial_cmdsn = 0 > node.session.initial_login_retry_max = 8 > node.session.xmit_thread_priority = -20 > node.session.cmds_max = 128 > node.session.queue_depth = 32 > node.session.auth.authmethod = CHAP > node.session.auth.username = devstack-1-1 > node.session.auth.password = ******** > node.session.auth.username_in = <empty> > node.session.auth.password_in = <empty> > node.session.timeo.replacement_timeout = 120 > node.session.err_timeo.abort_timeout = 15 > node.session.err_timeo.lu_reset_timeout = 20 > node.session.err_timeo.host_reset_timeout = 60 > node.session.iscsi.FastAbort = Yes > node.session.iscsi.InitialR2T = No > node.session.iscsi.ImmediateData = Yes > node.session.iscsi.FirstBurstLength = 262144 > node.session.iscsi.MaxBurstLength = 16776192 > node.session.iscsi.DefaultTime2Retain = 0 > node.session.iscsi.DefaultTime2Wait = 2 > node.session.iscsi.MaxConnections = 1 > node.session.iscsi.MaxOutstandingR2T = 1 > node.session.iscsi.ERL = 0 > node.conn[0].address = 192.168.69.211 > node.conn[0].port = 3260 > node.conn[0].startup = manual > node.conn[0].tcp.window_size = 524288 > node.conn[0].tcp.type_of_service = 0 > node.conn[0].timeo.logout_timeout = 15 > node.conn[0].timeo.login_timeout = 15 > node.conn[0].timeo.auth_timeout = 45 > node.conn[0].timeo.noop_out_interval = 5 > node.conn[0].timeo.noop_out_timeout = 5 > node.conn[0].iscsi.MaxRecvDataSegmentLength = 262144 > node.conn[0].iscsi.HeaderDigest = None > node.conn[0].iscsi.DataDigest = None > node.conn[0].iscsi.IFMarker = No > node.conn[0].iscsi.OFMarker = No > # END RECORD > stderr= from (pid=1090) _run_iscsiadm > /opt/stack/nova/nova/virt/libvirt/volume.py:98 > 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 192.168.69.211:3260 --op update -n node.session.auth.authmethod -v > CHAP from (pid=1090) execute /opt/stack/nova/nova/utils.py:201 > 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 > 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 192.168.69.211:3260 --op update -n node.session.auth.username -v > devstack-1-1 from (pid=1090) execute /opt/stack/nova/nova/utils.py:201 > 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 > 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 192.168.69.211:3260 --op update -n node.session.auth.password -v > DOMB9W14FK8R from (pid=1090) execute /opt/stack/nova/nova/utils.py:201 > 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 > 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 192.168.69.211:3260 --login from (pid=1090) execute > /opt/stack/nova/nova/utils.py:201 > 2011-12-23 10:36:19,855 DEBUG nova.utils [-] Result was 255 from > (pid=1090) execute /opt/stack/nova/nova/utils.py:217 > 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 > (nova.compute.manager): TRACE: Traceback (most recent call last): > (nova.compute.manager): TRACE: File > "/opt/stack/nova/nova/compute/manager.py", line 1510, in attach_volume > (nova.compute.manager): TRACE: mountpoint) > (nova.compute.manager): TRACE: File "/opt/stack/nova/nova/exception.py", > line 115, in wrapped > (nova.compute.manager): TRACE: return f(*args, **kw) > (nova.compute.manager): TRACE: File > "/opt/stack/nova/nova/virt/libvirt/connection.py", line 427, in > attach_volume > (nova.compute.manager): TRACE: mount_device) > (nova.compute.manager): TRACE: File > "/opt/stack/nova/nova/virt/libvirt/connection.py", line 419, in > volume_driver_method > (nova.compute.manager): TRACE: return method(connection_info, *args, > **kwargs) > (nova.compute.manager): TRACE: File > "/opt/stack/nova/nova/virt/libvirt/volume.py", line 128, in connect_volume > (nova.compute.manager): TRACE: self._run_iscsiadm(iscsi_properties, > ("--login",)) > (nova.compute.manager): TRACE: File > "/opt/stack/nova/nova/virt/libvirt/volume.py", line 96, in _run_iscsiadm > (nova.compute.manager): TRACE: check_exit_code=check_exit_code) > (nova.compute.manager): TRACE: File "/opt/stack/nova/nova/utils.py", > line 225, in execute > (nova.compute.manager): TRACE: cmd=' '.join(cmd)) > (nova.compute.manager): TRACE: ProcessExecutionError: Unexpected error > while running command. > (nova.compute.manager): TRACE: Command: sudo iscsiadm -m node -T > iqn.2010-01.com.solidfire:wmit.volume-00000002.51 -p > 192.168.69.211:3260--login > (nova.compute.manager): TRACE: Exit code: 255 > (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' > (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' > (nova.compute.manager): TRACE: > 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 > 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 > 2011-12-23 10:36:20,064 ERROR nova.rpc [-] Exception during message > handling > (nova.rpc): TRACE: Traceback (most recent call last): > (nova.rpc): TRACE: File "/opt/stack/nova/nova/rpc/impl_kombu.py", line > 627, in _process_data > (nova.rpc): TRACE: rval = node_func(context=ctxt, **node_args) > (nova.rpc): TRACE: File "/opt/stack/nova/nova/exception.py", line 115, > in wrapped > (nova.rpc): TRACE: return f(*args, **kw) > (nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line > 115, in decorated_function > (nova.rpc): TRACE: function(self, context, instance_uuid, *args, > **kwargs) > (nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line > 138, in decorated_function > (nova.rpc): TRACE: self.add_instance_fault_from_exc(context, > instance_uuid, e) > (nova.rpc): TRACE: File "/usr/lib/python2.7/contextlib.py", line 24, in > __exit__ > (nova.rpc): TRACE: self.gen.next() > (nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line > 133, in decorated_function > (nova.rpc): TRACE: return function(self, context, instance_uuid, > *args, **kwargs) > (nova.rpc): TRACE: File "/opt/stack/nova/nova/compute/manager.py", line > 1519, in attach_volume > (nova.rpc): TRACE: raise exc > (nova.rpc): TRACE: ProcessExecutionError: Unexpected error while running > command. > (nova.rpc): TRACE: Command: None > (nova.rpc): TRACE: Exit code: - > (nova.rpc): TRACE: Stdout: None > (nova.rpc): TRACE: Stderr: None > (nova.rpc): TRACE: > > > > > ~~~~ nova-volume.log~~~~~~~~~~~ > > 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 > 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 > 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 > 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 > 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 > 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 > >
_______________________________________________ Mailing list: https://launchpad.net/~openstack Post to : [email protected] Unsubscribe : https://launchpad.net/~openstack More help : https://help.launchpad.net/ListHelp
