Bug 1011193 - iSCSI Discovery fails
Summary: iSCSI Discovery fails
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: oVirt
Classification: Retired
Component: ovirt-node
Version: 3.3
Hardware: x86_64
OS: Linux
high
high
Target Milestone: ---
: 3.4.2
Assignee: Joey Boggs
QA Contact: bugs@ovirt.org
URL:
Whiteboard: node
Depends On: 1025401
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-09-23 18:09 UTC by Jonas Israelsson
Modified: 2014-07-18 15:49 UTC (History)
13 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-05-29 16:41:22 UTC
oVirt Team: ---


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


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 20772 0 None None None Never
oVirt gerrit 30445 0 master MERGED selinux: Add some iscsi + misc rules Never

Description Jonas Israelsson 2013-09-23 18:09:30 UTC
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 18:10:48 UTC
Created attachment 801844 [details]
Output from 'mount'

Comment 2 Jonas Israelsson 2013-09-23 18:11:23 UTC
Created attachment 801847 [details]
Output from 'df -h'

Comment 3 Jonas Israelsson 2013-09-23 18:13:22 UTC
Created attachment 801849 [details]
Output from 'find /var/lib/iscsi -ls'

Comment 4 Moritz Baumann 2013-10-01 14:41:40 UTC
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 14:33:30 UTC
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 21:28:31 UTC
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 09:17:47 UTC
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 16:41:22 UTC
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.