Bug 1011193 - iSCSI Discovery fails
iSCSI Discovery fails
Status: CLOSED CURRENTRELEASE
Product: oVirt
Classification: Community
Component: ovirt-node (Show other bugs)
3.3
x86_64 Linux
high Severity high
: ---
: 3.4.2
Assigned To: Joey Boggs
bugs@ovirt.org
node
:
Depends On: 1025401
Blocks:
  Show dependency treegraph
 
Reported: 2013-09-23 14:09 EDT by Jonas Israelsson
Modified: 2014-07-18 11:49 EDT (History)
13 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-05-29 12:41:22 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
dmesg output from the node (57.46 KB, text/plain)
2013-09-23 14:09 EDT, Jonas Israelsson
no flags Details
Output from 'mount' (14.88 KB, text/plain)
2013-09-23 14:10 EDT, Jonas Israelsson
no flags Details
Output from 'df -h' (3.22 KB, text/plain)
2013-09-23 14:11 EDT, Jonas Israelsson
no flags Details
Output from 'find /var/lib/iscsi -ls' (127 bytes, text/plain)
2013-09-23 14:13 EDT, Jonas Israelsson
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 20772 None None None Never
oVirt gerrit 30445 master MERGED selinux: Add some iscsi + misc rules Never

  None (edit)
Description Jonas Israelsson 2013-09-23 14:09:30 EDT
Created attachment 801843 [details]
dmesg output from the node

Trying to add a new iscsi storage domain fails while doing the iscsi_discovery and the following error is written to the engine error log.

2013-09-23 19:45:49,855 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp--127.0.0.1-8702-14) START, DiscoverSendTargetsVDSCommand(HostName = bagaren, HostId = 3bb080e5-d36d-4376-9cc0-f2f0b00c1439, connection={ id: null, connection: 192.168.24.200, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };), log id: 13d14411
2013-09-23 19:45:49,888 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp--127.0.0.1-8702-14) Command org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand return value
 IQNListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=475, mMessage=Failed discovery of iSCSI targets: "portal=IscsiPortal(hostname='192.168.24.200', port=3260), err=(6, [], ['iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13', '', 'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied', '', 'iscsiadm: Could not add new discovery record.'])"]]
2013-09-23 19:45:49,912 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp--127.0.0.1-8702-14) HostName = bagaren
2013-09-23 19:45:49,915 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp--127.0.0.1-8702-14) Command DiscoverSendTargetsVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to DiscoverSendTargetsVDS, error = Failed discovery of iSCSI targets: "portal=IscsiPortal(hostname='192.168.24.200', port=3260), err=(6, [], ['iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13', '', 'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied', '', 'iscsiadm: Could not add new discovery record.'])"
2013-09-23 19:45:49,931 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp--127.0.0.1-8702-14) FINISH, DiscoverSendTargetsVDSCommand, log id: 13d14411
2013-09-23 19:45:49,936 ERROR [org.ovirt.engine.core.bll.storage.DiscoverSendTargetsQuery] (ajp--127.0.0.1-8702-14) Query DiscoverSendTargetsQuery failed. Exception message is VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to DiscoverSendTargetsVDS, error = Failed discovery of iSCSI targets: "portal=IscsiPortal(hostname='192.168.24.200', port=3260), err=(6, [], ['iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13', '', 'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied', '', 'iscsiadm: Could not add new discovery record.'])" (Failed with VDSM error iSCSIDiscoveryError and code 475)


And this to the vdsm.log in the node.

Thread-4103::DEBUG::2013-09-23 17:39:48,809::BindingXMLRPC::177::vds::(wrapper) client [192.168.24.217]
Thread-4103::DEBUG::2013-09-23 17:39:48,810::task::579::TaskManager.Task::(_updateState) Task=`f49e993b-745c-4c91-800c-290331028bad`::moving from state init -> state preparing
Thread-4103::INFO::2013-09-23 17:39:48,810::logUtils::44::dispatcher::(wrapper) Run and protect: discoverSendTargets(con={'connection': '192.168.24.200', 'password': '******', 'port': '3260', 'user': ''}, options=None)
Thread-4103::DEBUG::2013-09-23 17:39:48,810::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 192.168.24.200:3260 --op=new' (cwd None)
Thread-4103::DEBUG::2013-09-23 17:39:48,820::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13\n\niscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied\n\niscsiadm: Could not add new discovery record.\n'; <rc> = 6
Thread-4103::DEBUG::2013-09-23 17:39:48,821::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m iface' (cwd None)
Thread-4103::DEBUG::2013-09-23 17:39:48,830::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
Thread-4103::ERROR::2013-09-23 17:39:48,830::hsm::2987::Storage.HSM::(discoverSendTargets) Discovery failed
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/hsm.py", line 2985, in discoverSendTargets
    targets = iscsi.discoverSendTargets(iface, portal, cred)
  File "/usr/share/vdsm/storage/iscsi.py", line 223, in discoverSendTargets
    addIscsiPortal(iface, portal, credentials)
  File "/usr/share/vdsm/storage/iscsi.py", line 184, in addIscsiPortal
    iscsiadm.discoverydb_new(discoverType, iface.name, portalStr)
  File "/usr/share/vdsm/storage/iscsiadm.py", line 176, in discoverydb_new
    raise IscsiDiscoverdbError(rc, out, err)
IscsiDiscoverdbError: (6, [], ['iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13', '', 'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied', '', 'iscsiadm: Could not add new discovery record.'])
Thread-4103::ERROR::2013-09-23 17:39:48,830::task::850::TaskManager.Task::(_setError) Task=`f49e993b-745c-4c91-800c-290331028bad`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 2988, in discoverSendTargets
    raise se.iSCSIDiscoveryError(portal, e)
iSCSIDiscoveryError: Failed discovery of iSCSI targets: "portal=IscsiPortal(hostname='192.168.24.200', port=3260), err=(6, [], ['iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13', '', 'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied', '', 'iscsiadm: Could not add new discovery record.'])"
Thread-4103::DEBUG::2013-09-23 17:39:48,831::task::869::TaskManager.Task::(_run) Task=`f49e993b-745c-4c91-800c-290331028bad`::Task._run: f49e993b-745c-4c91-800c-290331028bad ({'connection': '192.168.24.200', 'password': '', 'port': '3260', 'user': ''},) {} failed - stopping task
Thread-4103::DEBUG::2013-09-23 17:39:48,831::task::1194::TaskManager.Task::(stop) Task=`f49e993b-745c-4c91-800c-290331028bad`::stopping in state preparing (force False)
Thread-4103::DEBUG::2013-09-23 17:39:48,832::task::974::TaskManager.Task::(_decref) Task=`f49e993b-745c-4c91-800c-290331028bad`::ref 1 aborting True
Thread-4103::INFO::2013-09-23 17:39:48,832::task::1151::TaskManager.Task::(prepare) Task=`f49e993b-745c-4c91-800c-290331028bad`::aborting: Task is aborted: 'Failed discovery of iSCSI targets' - code 475
Thread-4103::DEBUG::2013-09-23 17:39:48,832::task::1156::TaskManager.Task::(prepare) Task=`f49e993b-745c-4c91-800c-290331028bad`::Prepare: aborted: Failed discovery of iSCSI targets
Thread-4103::DEBUG::2013-09-23 17:39:48,832::task::974::TaskManager.Task::(_decref) Task=`f49e993b-745c-4c91-800c-290331028bad`::ref 0 aborting True
Thread-4103::DEBUG::2013-09-23 17:39:48,833::task::909::TaskManager.Task::(_doAbort) Task=`f49e993b-745c-4c91-800c-290331028bad`::Task._doAbort: force False
Thread-4103::DEBUG::2013-09-23 17:39:48,833::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4103::DEBUG::2013-09-23 17:39:48,833::task::579::TaskManager.Task::(_updateState) Task=`f49e993b-745c-4c91-800c-290331028bad`::moving from state preparing -> state aborting
Thread-4103::DEBUG::2013-09-23 17:39:48,833::task::534::TaskManager.Task::(__state_aborting) Task=`f49e993b-745c-4c91-800c-290331028bad`::_aborting: recover policy none
Thread-4103::DEBUG::2013-09-23 17:39:48,834::task::579::TaskManager.Task::(_updateState) Task=`f49e993b-745c-4c91-800c-290331028bad`::moving from state aborting -> state failed
Thread-4103::DEBUG::2013-09-23 17:39:48,834::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-4103::DEBUG::2013-09-23 17:39:48,834::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-4103::ERROR::2013-09-23 17:39:48,834::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Failed discovery of iSCSI targets: "portal=IscsiPortal(hostname=\'192.168.24.200\', port=3260), err=(6, [], [\'iscsiadm: Could not make dir /var/lib/iscsi/send_targets/192.168.24.200,3260 err 13\', \'\', \'iscsiadm: Could not open /var/lib/iscsi/send_targets/192.168.24.200,3260: Permission denied\', \'\', \'iscsiadm: Could not add new discovery record.\'])"', 'code': 475}}

The engine is running in a virtual machine in a separate KVM host outside ovirt. The node it running (naturally) on a physical machine.
Everything have been just been (re)installed.

I have three nodes whereas two had previously been used as 2.3 nodes. I did however used the "reinstall" method that seem to repartition and reformat the local disk. Furthermore, when running into trouble just to be sure there where no leftovers I also scraped one of the nodes disk with dd and reinstalled it. Made no difference..

Part from the necessary configuration during install I have not really touched anything configuration wise.

Also, just to let you know there is nothing wrong with the target nor the communication, I am able to just fine run the discovery and set up the iscsi session manually and the luns become accessible to the node.

I even tried to the exact command that from the vdsm.log seem to be executed, that as well works just fine if executed manually.

[root@bagaren vdsm]# /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 192.168.24.200:3260 --op=new
New discovery record for [192.168.24.200,3260] added.

The engine is running on top of Fedora 19 and the nodes where installed with the following iso: ovirt-node-iso-3.0.1-1.0.2.vdsm.fc19.iso
Comment 1 Jonas Israelsson 2013-09-23 14:10:48 EDT
Created attachment 801844 [details]
Output from 'mount'
Comment 2 Jonas Israelsson 2013-09-23 14:11:23 EDT
Created attachment 801847 [details]
Output from 'df -h'
Comment 3 Jonas Israelsson 2013-09-23 14:13:22 EDT
Created attachment 801849 [details]
Output from 'find /var/lib/iscsi -ls'
Comment 4 Moritz Baumann 2013-10-01 10:41:40 EDT
ssh to the ovirt-node as root and doing a setenforce 0 is migitating the problem.


[root@ovirt-node vdsm]# audit2allow -alR

require {
	type unconfined_t;
	type sshd_net_t;
	type tuned_t;
	type virtd_t;
	type iscsid_t;
	type collectd_t;
	type initrc_t;
	type iscsi_var_lib_t;
	class process dyntransition;
	class unix_stream_socket connectto;
	class lnk_file { create unlink };
	class dir { write remove_name create add_name rmdir };
	class file { write create unlink };
}

#============= collectd_t ==============
allow collectd_t virtd_t:unix_stream_socket connectto;

#============= initrc_t ==============
allow initrc_t sshd_net_t:process dyntransition;
allow initrc_t unconfined_t:process dyntransition;

#============= iscsid_t ==============
allow iscsid_t iscsi_var_lib_t:dir { write remove_name create add_name rmdir };
allow iscsid_t iscsi_var_lib_t:file { write create unlink };
allow iscsid_t iscsi_var_lib_t:lnk_file { create unlink };

#============= tuned_t ==============

shows this.
Comment 5 Fabian Deutsch 2013-10-31 10:33:30 EDT
Dan,

shall the above rules go into Fedora or shall we add them to our own (ovirt node) module?
None of them seem to be specific to any of Node's quirks (e.g. tmpfs_t as a target, because Node is using much tmpfs stuff)-
Comment 6 Einav Cohen 2013-12-06 16:28:31 EST
FWIW: The exact same thing happened to me on a 'regular' Fedora 19 Host (not an ovirt-node Host) within my ovirt env. In addition, the mitigation from Comment #4 worked well in my case too.
Comment 7 Sandro Bonazzola 2014-03-04 04:17:47 EST
This is an automated message.
Re-targeting all non-blocker bugs still open on 3.4.0 to 3.4.1.
Comment 8 Joey Boggs 2014-05-29 12:41:22 EDT
this was fixed in 3.0.4 release, please reopen if it occurs again.

Note You need to log in before you can comment on or make changes to this bug.