Open Stack

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 at 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 at 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack/attachments/20111223/301068dd/attachment.html>