Bug 674822

Summary: connectStorageServer tries to delete scsi target that was returned as not exist
Product: [Retired] oVirt Reporter: Rami Vaknin <rvaknin>
Component: vdsmAssignee: Ayal Baron <abaron>
Status: CLOSED CURRENTRELEASE QA Contact:
Severity: medium Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: abaron, acathrow, bazulay, cww, danken, iheim, jkt, lpeer, mgoldboi, yeylon
Target Milestone: ---Keywords: Improvement
Target Release: 3.3.4   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: storage
Fixed In Version: Doc Type: Enhancement
Doc Text:
Story Points: ---
Clone Of: Environment:
RHEVM 2.3 with RHEL6 hosts
Last Closed: 2013-09-04 22:46:56 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
VDSM Log none

Description Rami Vaknin 2011-02-03 13:11:21 UTC
Created attachment 476776 [details]
VDSM Log

/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2011-01.com:Rami-04-40G -o update -n node.session.auth.authmethod -v CHAP
Thread-709::DEBUG::2011-02-03 14:23:12,163::iscsi::395::Storage.Misc.excCmd::(addiSCSINode) FAILED: <err> = 'iscsiadm: no records found!\n'; <rc> = 255
/usr/bin/sudo -n /sbin/iscsiadm -m node -o delete -T iqn.2011-01.com:Rami-04-40G -p 10.35.64.10:3260


How to reproduce:
1. Define host with iscsi Lun
2. Remove the Lun from the storage server itself
3. Enter the host into Maintenance and Activate it (in order to invoke connectStoragePool)


From VDSM log:

Thread-709::INFO::2011-02-03 14:23:11,971::dispatcher::94::Storage.Dispatcher.Protect::(run) Run and protect: connectStorageServer, args: (domType=3, spUUID=1af052ad-9b2c-4fa7-b445-9d64c71511ac, conList=[{'connection': '10.35.64.10
', 'iqn': 'iqn.2011-01.com:Rami-04-40G', 'portal': '1', 'user': '(null)', 'password': '******', 'id': 'b5fd4c37-413a-4ce5-9ce3-b691b6c8abb2', 'port': '3260'}])
Thread-709::DEBUG::2011-02-03 14:23:11,972::task::491::TaskManager.Task::(_debug) Task bab41350-5f71-4288-a3b0-b3af1f00b459: moving from state init -> state preparing
Thread-709::INFO::2011-02-03 14:23:11,972::storage_connection::78::Storage.ServerConnection::(connect) Request to connect ISCSI storage server
Thread-709::INFO::2011-02-03 14:23:11,972::storage_connection::41::Storage.ServerConnection::(__validateConnectionParams) conList=[{'connection': '10.35.64.10', 'iqn': 'iqn.2011-01.com:Rami-04-40G', 'portal': '1', 'user': '(null)',
 'password': '******', 'id': 'b5fd4c37-413a-4ce5-9ce3-b691b6c8abb2', 'port': '3260'}]
Thread-709::DEBUG::2011-02-03 14:23:11,973::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -p 10.35.64.10:3260 -o new' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:11,987::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:11,988::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -p 10.35.64.10:3260 -o update -n discovery.sendtargets.auth.aut
hmethod -v CHAP' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,002::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:12,003::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) '/sbin/iscsiadm -m discoverydb -t sendtargets -p 10.35.64.10:3260 -o update -n discovery.sendtargets.auth.password -v ******' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,016::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:12,017::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -p 10.35.64.10:3260 -o update -n discovery.sendtargets.auth.username -v (null)' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,031::iscsi::369::Storage.Misc.excCmd::(_configureAuthInformation) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:12,032::iscsi::318::Storage.Misc.excCmd::(addiSCSIPortal) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -p 10.35.64.10:3260 --discover' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,135::iscsi::318::Storage.Misc.excCmd::(addiSCSIPortal) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:12,136::iscsi::395::Storage.Misc.excCmd::(addiSCSINode) '/usr/bin/sudo -n /sbin/iscsiadm -m node -T iqn.2011-01.com:Rami-04-40G -o update -n node.session.auth.authmethod -v CHAP' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,163::iscsi::395::Storage.Misc.excCmd::(addiSCSINode) FAILED: <err> = 'iscsiadm: no records found!\n'; <rc> = 255
Thread-709::DEBUG::2011-02-03 14:23:12,164::misc::1008::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi._getiSCSISessionList)
Thread-709::DEBUG::2011-02-03 14:23:12,164::misc::1010::SamplingMethod::(__call__) Got in to sampling method
Thread-709::DEBUG::2011-02-03 14:23:12,164::iscsi::485::Storage.Misc.excCmd::(_getiSCSISessionList) '/usr/bin/sudo -n /sbin/iscsiadm -m session' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,178::iscsi::485::Storage.Misc.excCmd::(_getiSCSISessionList) SUCCESS: <err> = ''; <rc> = 0
Thread-709::DEBUG::2011-02-03 14:23:12,178::misc::1018::SamplingMethod::(__call__) Returning last result
Thread-709::DEBUG::2011-02-03 14:23:12,179::iscsi::540::Storage.iScsi::(checkSessionList) checkSession: dest ['connection: 10.35.64.10', 'iqn: iqn.2011-01.com:Rami-04-40G', 'portal: 1', 'user: (null)', 'port: 3260']
Thread-709::DEBUG::2011-02-03 14:23:12,179::iscsi::523::Storage.iScsi::(sameSession) enta key iqn v iqn.2011-01.com:Rami-05-60G != entb v iqn.2011-01.com:Rami-04-40G
Thread-709::DEBUG::2011-02-03 14:23:12,179::iscsi::460::Storage.Misc.excCmd::(remiSCSINode) '/usr/bin/sudo -n /sbin/iscsiadm -m node -o delete -T iqn.2011-01.com:Rami-04-40G -p 10.35.64.10:3260' (cwd None)
Thread-709::DEBUG::2011-02-03 14:23:12,205::iscsi::460::Storage.Misc.excCmd::(remiSCSINode) FAILED: <err> = 'iscsiadm: no records found!\n'; <rc> = 255
Thread-709::ERROR::2011-02-03 14:23:12,206::iscsi::434::Storage.iScsi::(addiSCSINode) Could not connect to iscsi node
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/iscsi.py", line 397, in addiSCSINode
    raise se.SetiSCSIAuthError(portal)
SetiSCSIAuthError: Set iSCSI authentication error: ('10.35.64.10:3260',)
Thread-709::ERROR::2011-02-03 14:23:12,206::storage_connection::212::Storage.ServerConnection::(__connectiSCSIServer) Error during storage connection: rc=461

Comment 2 Ayal Baron 2011-02-03 19:26:10 UTC
What's the bug here?

Comment 3 Moran Goldboim 2011-02-03 21:00:26 UTC
can you please explain the logic behind deleting a lun which wasn't found 10ms  beforehand

Comment 4 Rami Vaknin 2011-02-03 21:06:20 UTC
The bug is about an iscsiadm delete command that was performed without any reason.

This iscsi delete command was performed on the iqn.2011-01.com:Rami-04-40G Lun which does not exist anymore.
The return value and the error message of the last iscsiadm update command already indicated that there is no such Lun anymore, so obviously the iscsiadm delete command returned with error message.

Comment 9 Ayal Baron 2013-09-04 22:46:56 UTC
This was solved by http://gerrit.ovirt.org/#/c/2750/