STORAGEMODEL-226 raising RescanIsNeeded on AsiRequestQueueFullError

================================================================================

StorageModel / STORAGEMODEL-226
Rescan timed out after 300 seconds, with LOGICAL UNIT NOT SUPPORTED and TASK SET FULL

Type:              Bug                               Status:        Reopened                   Assignee: Guy Rozendorn
Priority:          Minor                             Resolution:    Unresolved                 Reporter: Omer Gertel
Affects Version/s: 0.1.51                            Fix Version/s: 0.1.63
Components: rescan_scsi_bus                                                                    Created: 2013-08-19 16:35
Labels:                                                                                        Updated: 2013-08-21 10:45

Issue Links:

Sub-Tasks:

Description:
In io008, centos, during node phase in and rescan, got Internal provisioning exception (Timeout). I've increased the timeout to 300 seconds in this run.

In the syslog I see some exceptions I'm not used to, especially the one regarding: "SCSI response status is not zero: 0x28 (driver status: 0x00, host status: 0x07)", pasted below.
This status, which infinio interprets as TASK_SET_FULL, usually means a queue is full on the host side and the task is refused and should be tried again.

The driver also reports:
{noformat}
Aug 19 15:38:00 io008 kernel: qla2xxx [0000:03:00.0]-3820:10: QUEUE FULL detected.
{noformat}

Exception in infinitest logs:

{noformat}
2013-08-19 15:37:58.641 Rescanning for logical units on Host io008
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000928 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000915 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000916 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000917 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000918 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000925 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000927 -> 15]
 --> Expecting to detect [50014380167cf9a8 -> 5742b0f000000926 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000928 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000915 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000916 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000917 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000918 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000925 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000927 -> 15]
 --> Expecting to detect [50014380167cf9aa -> 5742b0f000000926 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000928 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000915 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000916 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000917 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000918 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000925 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000927 -> 15]
 --> Expecting to detect [50014380167cf7c8 -> 5742b0f000000926 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000928 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000915 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000916 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000917 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000918 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000925 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000927 -> 15]
 --> Expecting to detect [50014380167cf7ca -> 5742b0f000000926 -> 15]

2013-08-19 15:42:59.919	Internal provisioning exception
Field	Action	Value
@fields.exception
Traceback (most recent call last):
 File "/opt/qa/infinitest/infinitest/provisioning.py", line 283, in _internal_provisioning_exception_context
 yield None
 File "/opt/qa/infinitest/infinitest/provisioning.py", line 364, in _rescan_logical_units
 , timeout_in_seconds = config.root.hosts.rescan_timeout_seconds, wait_on_rescan = wait_on_rescan)
 File "/opt/virtualenv/local/lib/python2.7/site-packages/rpyc-3.2.3-py2.7.egg/rpyc/core/netref.py", line 196, in __call__
 return syncreq(_self, consts.HANDLE_CALL, args, kwargs)
 File "/opt/virtualenv/local/lib/python2.7/site-packages/rpyc-3.2.3-py2.7.egg/rpyc/core/netref.py", line 71, in syncreq
 return conn.sync_request(handler, oid, *args)
 File "/opt/virtualenv/local/lib/python2.7/site-packages/rpyc-3.2.3-py2.7.egg/rpyc/core/protocol.py", line 438, in sync_request
 raise obj TimeoutError:
 ========= Remote Traceback (1) =========
 Traceback (most recent call last): File "/opt/infinidat/qa/env/lib/python2.7/site-packages/rpyc/core/protocol.py", line 300, in _dispatch_request res = self._HANDLERS[handler](self, *args) File "/opt/infinidat/qa/env/lib/python2.7/site-packages/rpyc/core/protocol.py", line 532, in _handle_call return self._local_objects[oid](*args, **dict(kwargs)) File "/opt/infinidat/qa/env/lib/python2.7/site-packages/infi.storagemodel-0.1.51-py2.7.egg/infi/storagemodel/base/__init__.py", line 107, in rescan_and_wait_for raise TimeoutError() # pylint: disable=W0710 TimeoutError
{noformat}

In the syslog I can see errors like this:
{noformat}
Aug 19 15:37:59 io008 [infi/qa/rpyc] -- 30596 multiprocessing caught unhandled exception#012Traceback (most recent call last):#012  File "/opt/infinidat/qa/env/lib/python2.7/site-packages/infi.storagemodel-0.1.51-py2.7.egg/infi/storagemodel/linux/rescan_scsi_bus/scsi.py", line 64, in do_scsi_cdb_with_in_process#012    func(sg_device,cdb )#012  Local variables:#012    'func': <function func at 0x1a248c0>#012    'cdb': StandardInquiryCommand(opcode=OperationCode(command_code=18, group_code=0) (const), evpd=0, <7 bits padding>, page_code=0, allocation_length=96, control=Control(<2 bits padding>, naca=0, <3 bits padding>, vendor_specific=0))#012    'sg_device': 'sg292'#012    'queue': <multiprocessing.queues.Queue object at 0x1a55490>#012    'sync_wait': <function sync_wait at 0x1422a28>#012    'exc_info': <built-in function exc_info>#012#012  File "/opt/infinidat/qa/env/lib/python2.7/site-packages/infi.storagemodel-0.1.51-py2.7.egg/infi/storagemodel/linux/rescan_scsi_bus/utils.py", line 83, in decorator#012    raise chain(ScsiCommandFailed())#012  Local variables:#012    'args': ('sg292', StandardInquiryCommand(opcode=OperationCode(command_code=18, group_code=0) (const), evpd=0, <7 bits padding>, page_code=0, allocation_length=96, control=Control(<2 bits padding>, naca=0, <3 bits padding>, vendor_specific=0)))#012    'AsiCheckConditionError': <class 'infi.asi.errors.AsiCheckConditionError'>#012    'cdb': StandardInquiryCommand(opcode=OperationCode(command_code=18, group_code=0) (const), evpd=0, <7 bits padding>, page_code=0, allocation_length=96, control=Control(<2 bits padding>, naca=0, <3 bits padding>, vendor_specific=0))#012    'kwargs': {}#012    'counter': 0#012    'sg_device': 'sg292'#012    'AsiSCSIError': <class 'infi.asi.errors.AsiSCSIError'>#012    'func': <function func at 0x1a247d0>#012    'error': AsiSCSIError('SCSI response status is not zero: 0x28 (driver status: 0x00, host status: 0x07)',)#012    'msg': '{} sg device {} got unrecoverable error {} during {}'#012    'response': None#012    'AsiOSError': <class 'infi
{noformat}
{noformat}
Aug 19 15:43:01 io008 [infi/qa/rpyc] -- 24945 sg device sg355 got ILLEGAL_REQUEST LOGICAL UNIT NOT SUPPORTED
Aug 19 15:43:01 io008 [infi/qa/rpyc] -- 24945 multiprocessing caught unhandled exception#012Traceback (most recent call last):#012
File "/opt/infinidat/qa/env/lib/python2.7/site-packages/infi.storagemodel-0.1.51-py2.7.egg/infi/storagemodel/linux/rescan_scsi_bus/s
csi.py", line 64, in do_scsi_cdb_with_in_process#012    func(sg_device,cdb )#012  Local variables:#012    'func': <function func at
0x12b0488>#012    'cdb': TestUnitReadyCommand(opcode=OperationCode(command_code=0, group_code=0) (const), <4 bytes padding>, control
=Control(<2 bits padding>, naca=0, <3 bits padding>, vendor_specific=0))#012    'sg_device': 'sg355'#012    'queue': <multiprocessin
g.queues.Queue object at 0x21be550>#012    'sync_wait': <function sync_wait at 0x1422a28>#012    'exc_info': <built-in function exc_
info>#012#012  File "/opt/infinidat/qa/env/lib/python2.7/site-packages/infi.storagemodel-0.1.51-py2.7.egg/infi/storagemodel/linux/re
scan_scsi_bus/utils.py", line 83, in decorator#012    raise chain(ScsiCommandFailed())#012  Local variables:#012    'code': 'LOGICAL
 UNIT NOT SUPPORTED'#012    'e': AsiCheckConditionError("SCSI Check Condition status, sense SCSISenseDataDescriptorBased(response_co
de=SCSISenseResponseCode(code=114, valid=0), sense_key='ILLEGAL_REQUEST', <4 bits padding>, additional_sense_code=AdditionalSenseCod
e(LOGICAL UNIT NOT SUPPORTED: code=0x25, qualifier=0x00), <2 bytes padding>, descriptors=[  ]) [720525000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
000000000000000000000000000000000000000000000000000000000000000000000000000000]",)#012    'func': <function func at 0x12b0500>#012
  'cdb': TestUnitReadyCommand(opcode=OperationCode(command_code=0, group_code=0) (c
Aug 19 15:43:01 io008 [infi/qa/rpyc] -- 23749 Test Unit Ready on sg355 raised an exception
{noformat}

Syslog is attached.

Comments:
Guy Rozendorn added a comment - 2013-08-21 09:21
syslog is not attached

Guy Rozendorn added a comment - 2013-08-21 09:24
You had 32 paths, and how many LUNs? looks like you exhausted the ports...

Omer Gertel added a comment - 2013-08-21 10:34
Yes, the host's queues were full.
I just wasn't sure if I should've gotten a more descriptive error, or, do you simply retry on these type of errors (REQUEUE, TASK_SET_FULL, etc.), and the rescan just timed out?

Also - Jira's ajax sucks. Apparently,  you can't upload a file when you create an issue in a modal form.

Omer Gertel added a comment - 2013-08-21 10:36
closed by mistake

Guy Rozendorn added a comment - 2013-08-21 10:45
oh yes u're right