Unfreezing dependencies
HIP-701 silence logging at atexit

causes "No handlers found for …" messages
HIP-704 MultipathDevicesAreReady

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

Host Power Tools / HIP-704
volume provisioning fails when RescanIsNeeded

Type:              Bug                               Status:        Open                       Assignee: Arnon Yaari
Priority:          Minor                             Resolution:    Unresolved                 Reporter: Arnon Yaari
Affects Version/s:                                   Fix Version/s: 1.1
Components: volume provisioning                                                                Created: 2013-08-20 15:15
Labels:                                                                                        Updated: 2013-08-20 15:15

Issue Links:

Sub-Tasks:

Description:
This following trace happens when RescanIsNeeded is raised during provisioning, causing {{run_volume_provision}} to be run twice.

{noformat}
======================================================================
ERROR: TestCase_8perf.test_8perf
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\jenkins\workspace\powertools\tests\integration\test_performance.py", line 45, in setUp
    self._execute_8prov('1GB')
  Local variables:
    'self': <test_performance.TestCase_8perf.test_8perf>
  File "C:\jenkins\workspace\powertools\tests\integration\test_performance.py", line 57, in _execute_8prov
    run_volume_provision(args)
  Local variables:
    'self': <test_performance.TestCase_8perf.test_8perf>
    'args': {'--mount': u'E:\\', '<size>': 1*GB, '--yes': True, '--name': 'host-ci27.infinidat.com-vol-20130820-1327', '--pool': 'default', '--type': 'thick', '--system': '20011', '--filesystem': 'NTFS'}
    'run_volume_provision': <function run_volume_provision at 0x03282EF0>
    'size': '1GB'
  File "C:\jenkins\workspace\powertools\src\infi\vendata\powertools\cli\engine.py", line 20, in decorator
    return func(*args, **kwargs)
  Local variables:
    'args': ({'--mount': u'E:\\', '<size>': 1*GB, '--yes': True, '--name': 'host-ci27.infinidat.com-vol-20130820-1327', '--pool': 'default', '--type': 'thick', '--system': '20011', '--filesystem': 'NTFS'},)
    'RescanIsNeeded': <class 'infi.storagemodel.errors.RescanIsNeeded'>
    'func': <function run_volume_provision at 0x0327A430>
    'kwargs': {}
  File "C:\jenkins\workspace\powertools\src\infi\vendata\powertools\cli\engine.py", line 77, in run_volume_provision
    prepare_provision_arguments(arguments)
  Local variables:
    'get_workout': <function get_workout at 0x03377C70>
    'in_provisioning': <function in_provisioning at 0x03377D70>
    'arguments': {'--mount': u'E:\\', '<size>': 1*GB, '--yes': True, '--name': 'host-ci27.infinidat.com-vol-20130820-1327', '--pool': 'default', '--type': 'thick', '--system': '20011', '--filesystem': 'NTFS'}
  File "C:\jenkins\workspace\powertools\src\infi\vendata\powertools\cli\engine.py", line 71, in prepare_provision_arguments
    arguments["<size>"] = convert_size(arguments["<size>"])
  Local variables:
    '_autodetect_system': <function _autodetect_system at 0x0327AC70>
    'arguments': {'--mount': u'E:\\', '<size>': 1*GB, '--yes': True, '--name': 'host-ci27.infinidat.com-vol-20130820-1327', '--pool': 'default', '--type': 'thick', '--system': '20011', '--filesystem': 'NTFS'}
    '_validate_system': <function _validate_system at 0x032E21B0>
  File "C:\jenkins\workspace\powertools\src\infi\vendata\powertools\cli\validate.py", line 37, in convert_size
    return from_string(string.upper())
  Local variables:
    'msg': TypeError('expected string or buffer',)
    'from_string': <function from_string at 0x023C1B70>
    'string': 1*GB
AttributeError: 'Capacity' object has no attribute 'upper'
{noformat}

The size is being converted twice, but {{convert_size}} doesn't support this

Comments:
buildout.cfg: changed isolated python version to v2.7.5.1
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
buildout.cfg: changed isolated python version to v2.7.5.2
STORAGEMODEL-228 fix gevent/gipc imoprt checks
Freezing dependencies
Finished release v0.1.62.