Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1585287

Summary:

iSCSI CHAP not working with 4.2 engine while working with 4.1 engine using a 4.2 host

Product:

Red Hat Enterprise Virtualization Manager

Reporter:

amashah

Component:

vdsm

Assignee:

Idan Shaby <ishaby>

Status:

CLOSED WORKSFORME

QA Contact:

Kevin Alon Goldblatt <kgoldbla>

Severity:

medium

Docs Contact:

Priority:

unspecified

Version:

4.2.3

CC:

aefrat, amashah, bcholler, dfediuck, ebenahar, ishaby, kgoldbla, lsurette, nsoffer, ratamir, sbonazzo, srevivo, tnisan, ycui

Target Milestone:

ovirt-4.2.7

Keywords:

Regression, Reopened

Target Release:

---

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2018-09-06 16:22:57 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

Storage

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
engine and vdsm logs	none
engine and vdsm logs	none

Description amashah 2018-06-01 18:08:57 UTC

Description of problem:

rhvm-appliance 4.2 where iSCSI / CHAP * auth fails Discovery/SendTargets during new deployment.

* Solidfire Element 8 with CHAP sessions

If repo's are changed to 4.1, rhvm-appliance-4.2-20180504 is removed and rhvm-appliance-4.1.20171102 is installed, deployment is successful.

Version-Release number of selected component (if applicable):

4.2.3

How reproducible:


Steps to Reproduce:
1. Install RHV-H 4.2.3
2. Subscribe 4.2 channels
3. Deploy with iSCSI storage using CHAP 

Actual results:

Storage should work, deployment should complete.


Expected results:

Storage should work

Additional info:

IscsiDiscoverdbError: (19, [], ['iscsiadm: Login authentication failed with target ', 'iscsiadm: discovery login to 192.168.2.60 failed, giving up 5', 'iscsiadm: Could not perform SendTargets discovery: encountered non-retryable iSCSI login failure'])

2018-05-31 14:03:15,180-0400 INFO  (jsonrpc/5) [vdsm.api] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=192.168.2.60:3260, err=(19, [], ['iscsiadm: Login authentication failed with target ', 'iscsiadm: discovery login to 192.168.2.60 failed, giving up 5', 'iscsiadm: Could not perform SendTargets discovery: encountered non-retryable iSCSI login failure'])"

Comment 1 Tal Nisan 2018-06-03 07:57:22 UTC

Since it's a deployment issue it should move to node

Comment 2 Sandro Bonazzola 2018-06-04 13:37:53 UTC

(In reply to Tal Nisan from comment #1)
> Since it's a deployment issue it should move to node

It's attaching a LUN to an engine.
The suspect here is a regression in iscsi-initiator-utils.

Note that the call here is done on vdsm side on the RHV-H 4.2 host.
Not sure how using a 4.1 engine with the 4.2 host can succeed when doing the same thine on a 4.2 engine it fails.

Moving back to storage, moving to component vdsm

Comment 6 Yaniv Kaul 2018-06-04 13:50:00 UTC

Severity...?

Comment 11 Nir Soffer 2018-07-05 10:11:44 UTC

(In reply to amashah from comment #0)
> How reproducible:
Can you answer this? how much time did you try? all failed? some?

Comment 12 Nir Soffer 2018-07-05 10:12:34 UTC

> Steps to Reproduce:
> 1. Install RHV-H 4.2.3
> 2. Subscribe 4.2 channels
> 3. Deploy with iSCSI storage using CHAP

Raz, can you reproduce this issue in the lab?

Comment 13 Nir Soffer 2018-07-05 10:13:58 UTC

> IscsiDiscoverdbError: (19, [], ['iscsiadm: Login authentication failed with
> target ', 'iscsiadm: discovery login to 192.168.2.60 failed, giving up 5',
> 'iscsiadm: Could not perform SendTargets discovery: encountered
> non-retryable iSCSI login failure'])
> 
> 2018-05-31 14:03:15,180-0400 INFO  (jsonrpc/5) [vdsm.api] FINISH
> discoverSendTargets error=Failed discovery of iSCSI targets:
> u"portal=192.168.2.60:3260, err=(19, [], ['iscsiadm: Login authentication
> failed with target ', 'iscsiadm: discovery login to 192.168.2.60 failed,
> giving up 5', 'iscsiadm: Could not perform SendTargets discovery:
> encountered non-retryable iSCSI login failure'])"

Idan, please discuss these errors with iscsiadm maintainers, we need to understand
what this error means.

Comment 14 Raz Tamir 2018-07-05 10:16:02 UTC

Elad,

Maybe worth asking RHV-H team to assist here

Comment 15 Raz Tamir 2018-07-05 10:17:29 UTC

restoring old needinfos

Comment 20 Idan Shaby 2018-07-11 12:27:46 UTC

(In reply to Raz Tamir from comment #14)
> Elad,
> 
> Maybe worth asking RHV-H team to assist here

Elad, can we please try to reproduce it in the lab, and also run it manually like Nir suggested in comment 16?
The need info on you was accidentally dropped, re-adding it.

Comment 21 Elad 2018-07-11 13:46:29 UTC

Does it have to be tested with RHV-H?

Comment 22 Idan Shaby 2018-07-12 05:31:38 UTC

No, I don't think so.

Comment 23 Elad 2018-07-12 08:04:18 UTC

Kevin, I think we have a targetcli deployed we can use for CHAP testing. Can you please test the scenario?

Comment 25 Kevin Alon Goldblatt 2018-07-18 15:14:21 UTC

Ran with the following code:
----------------------------------------
ovirt-engine-4.2.4.4-0.1.el7_3.noarch
vdsm-4.20.31-1.el7ev.x86_64

Ran with the following scenario:
----------------------------------------
1. Tried creating a block storage domain with Chap authentication >>>>> Operation failed


vdsm.log:
--------------------------
2018-07-18 18:07:33,863+0300 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.03 seconds (__init__:573)
2018-07-18 18:07:34,500+0300 INFO  (jsonrpc/7) [vdsm.api] START discoverSendTargets(con={'ipv6_enabled': False, 'connection': u'10.35.83.188', 'password': '********', 'port': u'3260', 'user': u'admin'}, options=
None) from=::ffff:10.35.163.161,47740, flow_id=cba36799-de7e-4e1c-93de-859eaf8b7a04, task_id=a1c37765-d518-439f-869d-f84a40b650e3 (api:46)
2018-07-18 18:07:36,057+0300 ERROR (jsonrpc/7) [storage.HSM] Discovery failed (hsm:2956)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2954, in discoverSendTargets
    targets = iscsi.discoverSendTargets(iface, portal, cred)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsi.py", line 274, in discoverSendTargets
    str(portal))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsiadm.py", line 256, in discoverydb_discover
    raise IscsiAuthenticationError(rc, out, err)
IscsiAuthenticationError: (24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendT
argets discovery: iSCSI login failed due to authorization failure'])
2018-07-18 18:07:36,060+0300 INFO  (jsonrpc/7) [vdsm.api] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate wit
h target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" from=::ff
ff:10.35.163.161,47740, flow_id=cba36799-de7e-4e1c-93de-859eaf8b7a04, task_id=a1c37765-d518-439f-869d-f84a40b650e3 (api:50)
2018-07-18 18:07:36,061+0300 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='a1c37765-d518-439f-869d-f84a40b650e3') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in discoverSendTargets
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2957, in discoverSendTargets
    raise se.iSCSIDiscoveryError(portal, e)
iSCSIDiscoveryError: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initi
ator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-07-18 18:07:36,062+0300 INFO  (jsonrpc/7) [storage.TaskManager.Task] (Task='a1c37765-d518-439f-869d-f84a40b650e3') aborting: Task is aborted: 'Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, 
err=(24, [], [\'iscsiadm: Login failed to authenticate with target \', \'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization\', \'iscsiadm: Could not perform SendTargets discovery:
 iSCSI login failed due to authorization failure\'])"' - code 475 (task:1181)
2018-07-18 18:07:36,063+0300 ERROR (jsonrpc/7) [storage.Dispatcher] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" (dispatcher:82)



Engine.log:
----------------------------------------------
2018-07-18 18:07:27,944+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM
 vm-83-162.scl.lab.tlv.redhat.com command DiscoverSendTargetsVDS failed: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsi
adm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-07-18 18:07:27,944+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] Command 'org.ovirt.engine.core.vdsbroker.vdsbro
ker.DiscoverSendTargetsVDSCommand' return value 'IQNListReturn:{status='Status [code=475, message=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authentic
ate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"]'}
'
2018-07-18 18:07:27,944+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] HostName = vm-83-162.scl.lab.tlv.redhat.com
2018-07-18 18:07:27,944+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] Command 'DiscoverSendTargetsVDSCommand(HostName
 = vm-83-162.scl.lab.tlv.redhat.com, DiscoverSendTargetsVDSCommandParameters:{hostId='8b9da7d0-8572-46df-9c6e-845af226be1e', connection='StorageServerConnections:{id='null', connection='10.35.83.188', iqn='null'
, vfsType='null', mountOptions='null', nfsVersion='null', nfsRetrans='null', nfsTimeo='null', iface='null', netIfaceName='null'}'})' execution failed: VDSGenericException: VDSErrorException: Failed in vdscommand
 to DiscoverSendTargetsVDS, error = Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 
rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-07-18 18:07:27,944+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] FINISH, DiscoverSendTargetsVDSCommand, log id: 
55fef99
2018-07-18 18:07:27,944+03 ERROR [org.ovirt.engine.core.bll.storage.connection.DiscoverSendTargetsQuery] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] Query 'DiscoverSendTargetsQuery' failed: EngineEx
ception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to DiscoverSendTargetsVDS, error = Failed discovery of iSCSI targets: u"portal=1
0.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTarge
ts discovery: iSCSI login failed due to authorization failure'])" (Failed with error iSCSIDiscoveryError and code 475)
2018-07-18 18:07:27,944+03 ERROR [org.ovirt.engine.core.bll.storage.connection.DiscoverSendTargetsQuery] (default task-16) [cba36799-de7e-4e1c-93de-859eaf8b7a04] Exception: org.ovirt.engine.core.common.errors.En
gineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to DiscoverSendTargetsVDS, error = Failed discovery of iS
CSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Coul
d not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" (Failed with error iSCSIDiscoveryError and code 475)
        at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:]
        at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:]
        at org.ovirt.engine.core.bll.QueriesCommandBase.runVdsCommand(QueriesCommandBase.java:238) [bll.jar:]
        at org.ovirt.engine.core.bll.storage.connection.DiscoverSendTargetsQuery.executeQueryCommand(DiscoverSendTargetsQuery.java:18) [bll.jar:]
        at org.ovirt.engine.core.bll.QueriesCommandBase.executeCommand(QueriesCommandBase.java:106) [bll.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) [dal.jar:]
        at org.ovirt.engine.core.bll.executor.DefaultBackendQueryExecutor.execute(DefaultBackendQueryExecutor.java:14) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runQueryImpl(Backend.java:538) [bll.jar:]
        at org.ovirt.engine.core.bll.Backend.runQuery(Backend.java:507) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor85.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.jboss.as.weld.ejb.DelegatingInterceptorInvocationContext.proceed(DelegatingInterceptorInvocationContext.java:92) [wildfly-weld-ejb-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.interceptorChainCompleted(WeldInvocationContextImpl.java:124) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:143) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:]
        at sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.invokeNext(WeldInvocationContextImpl.java:109) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.WeldInvocationContextImpl.proceed(WeldInvocationContextImpl.java:141) [weld-core-impl.jar:2.4.7.Final-redhat-1]
  at org.jboss.as.weld.interceptors.Jsr299BindingsInterceptor.processInvocation(Jsr299BindingsInterceptor.java:101)
        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:63)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.ovirt.engine.core.bll.interceptors.CorrelationIdTrackerInterceptor.aroundInvoke(CorrelationIdTrackerInterceptor.java:13) [bll.jar:]
        at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptor.java:89)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ee.concurrent.ConcurrentContextInterceptor.processInvocation(ConcurrentContextInterceptor.java:45) [wildfly-ee-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:40)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:52)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:264) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:379) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:244) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
        at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-7.1.3.GA-redhat-2.jar:7.1.3.GA-redhat-2]
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
 at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
        at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
        at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185)
        at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81)
        at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view4.runQuery(Unknown Source) [common.jar:]
        at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.runQuery(GenericApiGWTServiceImpl.java:90)
        at sun.reflect.GeneratedMethodAccessor92.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at com.google.gwt.user.server.rpc.RPC.invokeAndEncodeResponse(RPC.java:587)
        at com.google.gwt.user.server.rpc.RemoteServiceServlet.processCall(RemoteServiceServlet.java:333)
        at com.google.gwt.user.server.rpc.RemoteServiceServlet.processCall(RemoteServiceServlet.java:303)
        at com.google.gwt.user.server.rpc.RemoteServiceServlet.processPost(RemoteServiceServlet.java:373)
        at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1]
        at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.service(GenericApiGWTServiceImpl.java:78)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec.jar:1.0.0.Final-redhat-1]
        at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
        at org.ovirt.engine.core.utils.servlet.HeaderFilter.doFilter(HeaderFilter.java:94) [utils.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at org.ovirt.engine.core.utils.servlet.CachingFilter.doFilter(CachingFilter.java:133) [utils.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at org.ovirt.engine.core.branding.BrandingFilter.doFilter(BrandingFilter.java:73) [branding.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at org.ovirt.engine.core.utils.servlet.LocaleFilter.doFilter(LocaleFilter.java:65) [utils.jar:]
        at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
        at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
        at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
        at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
        at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:64)
        at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
        at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
        at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:53)
        at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
        at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
        at io.undertow.servlet.handlers.security.ServletSecurityConstraintHandler.handleRequest(ServletSecurityConstraintHandler.java:59)
        at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
  at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
        at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
        at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
        at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
        at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
        at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
        at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
        at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
        at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501)
        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501)
        at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1501)
        at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
        at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
        at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
        at io.undertow.server.Connectors.executeRootHandler(Connectors.java:330)
        at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:812)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_171]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_171]
        at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_171]
Caused by: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed in vdscommand to DiscoverSendTargetsVDS, error = Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
        at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:184) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand.executeVdsBrokerCommand(DiscoverSendTargetsVDSCommand.java:27) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVdsCommandWithNetworkEvent(VdsBrokerCommand.java:123) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:111) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73) [vdsbroker.jar:]
        at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) [dal.jar:]
        at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:399) [vdsbroker.jar:]
        at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown Source) [vdsbroker.jar:]
        at sun.reflect.GeneratedMethodAccessor126.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:79) [weld-core-impl.jar:2.4.7.Final-redhat-1]
      at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:]
        at sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source) [:1.8.0_171]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_171]
        at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_171]
        at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:85) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:57) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [weld-core-impl.jar:2.4.7.Final-redhat-1]
        at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source) [vdsbroker.jar:]
        ... 148 more

Comment 26 Kevin Alon Goldblatt 2018-07-18 15:25:12 UTC

Created attachment 1459736 [details]
engine and vdsm logs

Added logs

Comment 27 Idan Shaby 2018-07-19 05:40:43 UTC

Thanks Kevin!
Can you please also check that it previously worked with a 4.1 engine, and most important - check if you can log in manually, as Nir asked in comment 16?

Comment 28 Kevin Alon Goldblatt 2018-07-22 11:39:45 UTC

(In reply to Idan Shaby from comment #27)
> Thanks Kevin!
> Can you please also check that it previously worked with a 4.1 engine, and
> most important - check if you can log in manually, as Nir asked in comment
> 16?

I ran the following manual commands as performed by the vdsm as they appear in the DEBUG log:

[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m session -R
iscsiadm: No session found.
[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/3514f0c5a5160049e|/dev/mapper/3514f0c5a5160049f|/dev/mapper/3514f0c5a516004a0|/dev/mapper/3514f0c5a516004a1|/dev/mapper/3514f0c5a516004a2|/dev/mapper/3514f0c5a516004a3|/dev/mapper/3514f0c5a51600674|/dev/mapper/3514f0c5a516017a3|/dev/mapper/3514f0c5a516017a4|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size,mda_used_count
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 32212189184: Input/output error
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 32212246528: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a51600674 was disabled
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a2 was disabled
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a5160049e was disabled
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a5160049f was disabled
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516017a4 was disabled
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516017a3 was disabled
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a1 was disabled
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a0 was disabled
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a3 was disabled
[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/lvm pvs --config ' devices { preferred_names = ["^/dev/mapper/"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ '\''a|/dev/mapper/3514f0c5a5160049e|/dev/mapper/3514f0c5a5160049f|/dev/mapper/3514f0c5a516004a0|/dev/mapper/3514f0c5a516004a1|/dev/mapper/3514f0c5a516004a2|/dev/mapper/3514f0c5a516004a3|/dev/mapper/3514f0c5a51600674|/dev/mapper/3514f0c5a516017a3|/dev/mapper/3514f0c5a516017a4|'\'', '\''r|.*|'\'' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } ' --noheadings --units b --nosuffix --separator '|' --ignoreskippedcluster -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size,mda_used_count
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 32212189184: Input/output error
  /dev/mapper/3514f0c5a51600674: read failed after 0 of 4096 at 32212246528: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a51600674 was disabled
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a2: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a2 was disabled
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a5160049e: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a5160049e was disabled
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a5160049f: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a5160049f was disabled
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516017a4: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516017a4 was disabled
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516017a3: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516017a3 was disabled
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a1: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a1 was disabled
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 161061208064: Input/output error
  /dev/mapper/3514f0c5a516004a0: read failed after 0 of 4096 at 161061265408: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a0 was disabled
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 0: Input/output error
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 53687025664: Input/output error
  /dev/mapper/3514f0c5a516004a3: read failed after 0 of 4096 at 53687083008: Input/output error
  WARNING: Error counts reached a limit of 3. Device /dev/mapper/3514f0c5a516004a3 was disabled
[root@vm-83-162 ~]#  /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover 
10.35.83.188:3260,1 iqn.2008-05.com.xtremio:xio00153500071-514f0c50023f6c00
10.35.83.188:3260,1 iqn.2015-03.com.iofabric:ovirt-master-00
10.35.83.188:3260,1 iqn.2015-08.com.randomuser:444
10.35.83.188:3260,1 iqn.2015-08.com.admin:444
[root@vm-83-162 ~]#  /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m iface 
default tcp,<empty>,<empty>,<empty>,<empty>
iser iser,<empty>,<empty>,<empty>,<empty>
[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=delete
[root@vm-83-162 ~]#

Comment 29 Kevin Alon Goldblatt 2018-07-22 11:41:44 UTC

Created attachment 1469747 [details]
engine and vdsm logs

Adding new logs after running the scenario again with DEBUG enabled

Comment 30 Kevin Alon Goldblatt 2018-07-22 12:52:34 UTC

Error reported in vdsm.log with DEBUG level set
------------------------------------------------
2018-07-22 14:18:10,309+0300 ERROR (jsonrpc/5) [storage.HSM] Discovery failed (hsm:2956)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2954, in discoverSendTargets
    targets = iscsi.discoverSendTargets(iface, portal, cred)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsi.py", line 274, in discoverSendTargets
    str(portal))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsiadm.py", line 256, in discoverydb_discover
    raise IscsiAuthenticationError(rc, out, err)
IscsiAuthenticationError: (24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendT
argets discovery: iSCSI login failed due to authorization failure'])
2018-07-22 14:18:10,311+0300 INFO  (jsonrpc/5) [vdsm.api] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate wit
h target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" from=::ff
ff:10.35.163.161,51670, flow_id=f9cf30f3-d181-4b33-b665-59ccc4fc2216, task_id=b133d12c-6b71-4a2b-8db0-12ac18f572b5 (api:50)
2018-07-22 14:18:10,312+0300 ERROR (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in discoverSendTargets
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2957, in discoverSendTargets
    raise se.iSCSIDiscoveryError(portal, e)
iSCSIDiscoveryError: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initi
ator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-07-22 14:18:10,312+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') Task._run: b133d12c-6b71-4a2b-8db0-12ac18f572b5 ({'ipv6_enabled': False, 'connection': u'10
.35.83.188', 'password': '********', 'port': u'3260', 'user': u'admin'},) {} failed - stopping task (task:894)
2018-07-22 14:18:10,312+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') stopping in state failed (force False) (task:1256)
2018-07-22 14:18:10,312+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') ref 1 aborting True (task:1002)
2018-07-22 14:18:10,313+0300 INFO  (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') aborting: Task is aborted: 'Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], [\'iscsiadm: Login failed to authenticate with target \', \'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization\', \'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure\'])"' - code 475 (task:1181)
2018-07-22 14:18:10,313+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') Prepare: aborted: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" (task:1186)
2018-07-22 14:18:10,313+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') ref 0 aborting True (task:1002)
2018-07-22 14:18:10,313+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') Task._doAbort: force False (task:937)
2018-07-22 14:18:10,314+0300 DEBUG (jsonrpc/5) [storage.ResourceManager.Owner] Owner.cancelAll requests {} (resourceManager:947)
2018-07-22 14:18:10,314+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') moving from state failed -> state aborting (task:602)
2018-07-22 14:18:10,314+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') _aborting: recover policy none (task:557)
2018-07-22 14:18:10,314+0300 DEBUG (jsonrpc/5) [storage.TaskManager.Task] (Task='b133d12c-6b71-4a2b-8db0-12ac18f572b5') moving from state failed -> state failed (task:602)
2018-07-22 14:18:10,314+0300 DEBUG (jsonrpc/5) [storage.ResourceManager.Owner] Owner.releaseAll requests {} resources {} (resourceManager:910)
2018-07-22 14:18:10,315+0300 DEBUG (jsonrpc/5) [storage.ResourceManager.Owner] Owner.cancelAll requests {} (resourceManager:947)
2018-07-22 14:18:10,315+0300 ERROR (jsonrpc/5) [storage.Dispatcher] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" (dispatcher:82)
2018-07-22 14:18:10,316+0300 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call ISCSIConnection.discoverSendTargets failed (error 475) in 1.69 seconds (__init__:573)
2018-07-22 14:18:11,202+0300 INFO  (jsonrpc/4) [api.host] START getAllVmStats() from=::1,58788 (api:46)
2018-07-22 14:18:11,203+0300 INFO  (jsonrpc/4) [api.host] FINISH getAllVmStats return={'status': {'message': 'Done', 'code': 0}, 'statsList': (suppressed)} from=::1,58788 (api:52)
2018-07-22 14:18:11,203+0300 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:573)
2018-07-22 14:18:17,852+0300 INFO  (jsonrpc/6) [api.host] START getAllVmStats() from=::ffff:10.35.163.161,51670 (api:46)
2018-07-22 14:18:17,852+0300 INFO  (jsonrpc/6) [api.host] FINISH getAllVmStats return={'status': {'message': 'Done', 'code': 0}, 'statsList': (suppressed)} from=::ffff:10.35.163.161,51670 (api:52)
2018-07-22 14:18:17,853+0300 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:573)
2018-07-22 14:18:23,281+0300 INFO  (jsonrpc/0) [api.host] START getStats() from=::ffff:10.35.163.161,51670 (api:46)
2018-07-22 14:18:23,282+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263') moving from state finished -> state preparing (task:602)
2018-07-22 14:18:23,283+0300 INFO  (jsonrpc/0) [vdsm.api] START repoStats(domains=()) from=::ffff:10.35.163.161,51670, task_id=c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263 (api:46)
2018-07-22 14:18:23,283+0300 INFO  (jsonrpc/0) [vdsm.api] FINISH repoStats return={} from=::ffff:10.35.163.161,51670, task_id=c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263 (api:52)
2018-07-22 14:18:23,283+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263') finished: {} (task:1201)
2018-07-22 14:18:23,283+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263') moving from state finished -> state finished (task:602)
2018-07-22 14:18:23,284+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.releaseAll requests {} resources {} (resourceManager:910)
2018-07-22 14:18:23,284+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.cancelAll requests {} (resourceManager:947)
2018-07-22 14:18:23,284+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='c1b0e13a-4dc0-42d7-ad3b-7e7ad966f263') ref 0 aborting False (task:1002)
2018-07-22 14:18:23,284+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='160c6ffd-fd2e-4436-b8ae-eb8979be23b8') moving from state finished -> state preparing (task:602)
2018-07-22 14:18:23,286+0300 INFO  (jsonrpc/0) [vdsm.api] START multipath_health() from=::ffff:10.35.163.161,51670, task_id=160c6ffd-fd2e-4436-b8ae-eb8979be23b8 (api:46)
2018-07-22 14:18:23,286+0300 INFO  (jsonrpc/0) [vdsm.api] FINISH multipath_health return={} from=::ffff:10.35.163.161,51670, task_id=160c6ffd-fd2e-4436-b8ae-eb8979be23b8 (api:52)
2018-07-22 14:18:23,286+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='160c6ffd-fd2e-4436-b8ae-eb8979be23b8') finished: {} (task:1201)
2018-07-22 14:18:23,286+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='160c6ffd-fd2e-4436-b8ae-eb8979be23b8') moving from state finished -> state finished (task:602)
2018-07-22 14:18:23,287+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.releaseAll requests {} resources {} (resourceManager:910)
2018-07-22 14:18:23,287+0300 DEBUG (jsonrpc/0) [storage.ResourceManager.Owner] Owner.cancelAll requests {} (resourceManager:947)
2018-07-22 14:18:23,287+0300 DEBUG (jsonrpc/0) [storage.TaskManager.Task] (Task='160c6ffd-fd2e-4436-b8ae-eb8979be23b8') ref 0 aborting False (task:1002)

Comment 31 Idan Shaby 2018-07-25 07:02:29 UTC

Thanks Kevin!

I am not sure which commands you tried to run, but I saw these commands in your vdsm log:

2018-07-22 14:18:08,626+0300 DEBUG (jsonrpc/5) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=new (cwd None) (commands:65)
2018-07-22 14:18:08,857+0300 DEBUG (jsonrpc/5) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (cwd None) (commands:65)
2018-07-22 14:18:09,085+0300 DEBUG (jsonrpc/5) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd None) (commands:65)
2018-07-22 14:18:09,301+0300 DEBUG (jsonrpc/5) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd None) (commands:65)
2018-07-22 14:18:09,525+0300 DEBUG (jsonrpc/5) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover (cwd None) (commands:65)

Can you try to run those manually (with the right password) and see if you manage to log in successfully?
Also, did you try to add a block domain using CHAP on 4.1?

Comment 32 Elad 2018-07-26 10:17:57 UTC

Hi Idan, sorry, currently we don't have the capacity for Kevin to test it over 4.1. 
We've tested CHAP on 4.1, it worked fine.

Kevin will answer your first question soon.

Thanks

Comment 33 Kevin Alon Goldblatt 2018-07-26 10:22:25 UTC

Hi,

I did not try running the same on  4.1 system


[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.authmethod -v 'CHAP' --op=update
[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.username -v 'admin' --op=update
[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.password -v 'admin' --op=update
[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover
iscsiadm: Login failed to authenticate with target

Comment 34 Kevin Alon Goldblatt 2018-08-07 11:18:52 UTC

using the 4.1 Engine and the 4.2 host produced the same result with a failed authentication:

2018-08-07 14:09:46,860+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=new (cwd No
ne) (commands:65)
2018-08-07 14:09:47,078+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,079+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (c
wd None) (commands:65)
2018-08-07 14:09:47,339+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,341+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd
 None) (commands:65)
2018-08-07 14:09:47,563+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,565+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd
 None) (commands:65)
2018-08-07 14:09:47,784+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,786+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover (cwd 
None) (commands:65)
2018-08-07 14:09:48,036+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] FAILED: <err> = 'iscsiadm: Login failed to authenticate with target \niscsiadm: discovery login to 10.35.83.188 rejected: initiator failed aut
horization\niscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure\n'; <rc> = 24 (commands:86)
2018-08-07 14:09:48,037+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m iface (cwd None) (commands:65)
2018-08-07 14:09:48,244+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:48,245+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=delete (cwd
 None) (commands:65)
2018-08-07 14:09:48,465+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:48,467+0300 ERROR (jsonrpc/7) [storage.HSM] Discovery failed (hsm:2956)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2954, in discoverSendTargets
    targets = iscsi.discoverSendTargets(iface, portal, cred)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsi.py", line 274, in discoverSendTargets
    str(portal))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsiadm.py", line 256, in discoverydb_discover
    raise IscsiAuthenticationError(rc, out, err)
IscsiAuthenticationError: (24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendT
argets discovery: iSCSI login failed due to authorization failure'])
2018-08-07 14:09:48,468+0300 INFO  (jsonrpc/7) [vdsm.api] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate wit
h target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" from=::ff
ff:10.35.161.181,44070, flow_id=bcde9994-60e1-45a4-b8b3-68ac5197c383, task_id=6ba5b6b1-6a1b-40ad-b067-9a3629bf943a (api:50)
2018-08-07 14:09:48,469+0300 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in discoverSendTargets
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2957, in discoverSendTargets
    raise se.iSCSIDiscoveryError(portal, e)
iSCSIDiscoveryError: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-08-07 14:09:48,469+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') Task._run: 6ba5b6b1-6a1b-40ad-b067-9a3629bf943a ({'ipv6_enabled': False, 'connection': u'10.35.83.188', 'password': '********', 'port': u'3260', 'user': u'admin'},) {} failed - stopping task (task:894)
2018-08-07 14:09:48,470+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') stopping in state failed (force False) (task:1256)
2018-08-07 14:09:48,470+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') ref 1 aborting True (task:1002)
2018-08-07 14:09:48,470+0300 INFO  (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') aborting: Task is aborted: 'Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], [\'iscsiadm: Login failed to authenticate with target \', \'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization\', \'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure\'])"' - code 475 (task:1181)

Comment 35 Idan Shaby 2018-08-16 09:58:10 UTC

Hi,

I tried to discover + login to a target that requires authentication for both actions. I first made sure that I cannot do either without authenticating and then I tried to discover + login using:
- master engine + master vdsm
- 4.2 engine + 4.2 vdsm
Both scenarios were successful, and the storage domain was created.

Since the client managed to create the domain by configuring his storage, and since I couldn't reproduce it in any of the environments mentioned, I am closing this bug.
If this issue reoccurs, please reopen.

Comment 36 Tal Nisan 2018-08-22 11:59:38 UTC

Idan, it seems like Kevin managed to reproduce, please work with him to understand what is going on here

Comment 37 Idan Shaby 2018-08-22 12:47:00 UTC

Kevin, any news about this?
From what you wrote here so far, you couldn't discover nor log in to a target using authentication at all. Am I wrong?

Comment 38 Kevin Alon Goldblatt 2018-08-26 09:09:56 UTC

(In reply to Idan Shaby from comment #37)
> Kevin, any news about this?
> From what you wrote here so far, you couldn't discover nor log in to a
> target using authentication at all. Am I wrong?

As per comment 34. I ran the same test with a 4.1 engine and a 4.2 host with the same result as when I used a 4.2 engine and 4.2 host. These are the commnands I ran:

[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.authmethod -v 'CHAP' --op=update

[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.username -v 'admin' --op=update

[root@vm-83-162 ~]# /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.password -v 'admin' --op=update

[root@vm-83-162 ~]# /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover
iscsiadm: Login failed to authenticate with target


2018-08-07 14:09:46,860+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=new (cwd No
ne) (commands:65)
2018-08-07 14:09:47,078+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,079+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.authmethod -v '****' --op=update (c
wd None) (commands:65)
2018-08-07 14:09:47,339+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,341+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.username -v '****' --op=update (cwd
 None) (commands:65)
2018-08-07 14:09:47,563+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,565+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 -n discovery.sendtargets.auth.password -v '****' --op=update (cwd
 None) (commands:65)
2018-08-07 14:09:47,784+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:47,786+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --discover (cwd 
None) (commands:65)
2018-08-07 14:09:48,036+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] FAILED: <err> = 'iscsiadm: Login failed to authenticate with target \niscsiadm: discovery login to 10.35.83.188 rejected: initiator failed aut
horization\niscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure\n'; <rc> = 24 (commands:86)
2018-08-07 14:09:48,037+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m iface (cwd None) (commands:65)
2018-08-07 14:09:48,244+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:48,245+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-0 /usr/bin/sudo -n /sbin/iscsiadm -m discoverydb -t sendtargets -I default -p 10.35.83.188:3260 --op=delete (cwd
 None) (commands:65)
2018-08-07 14:09:48,465+0300 DEBUG (jsonrpc/7) [storage.Misc.excCmd] SUCCESS: <err> = ''; <rc> = 0 (commands:86)
2018-08-07 14:09:48,467+0300 ERROR (jsonrpc/7) [storage.HSM] Discovery failed (hsm:2956)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2954, in discoverSendTargets
    targets = iscsi.discoverSendTargets(iface, portal, cred)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsi.py", line 274, in discoverSendTargets
    str(portal))
  File "/usr/lib/python2.7/site-packages/vdsm/storage/iscsiadm.py", line 256, in discoverydb_discover
    raise IscsiAuthenticationError(rc, out, err)
IscsiAuthenticationError: (24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendT
argets discovery: iSCSI login failed due to authorization failure'])
2018-08-07 14:09:48,468+0300 INFO  (jsonrpc/7) [vdsm.api] FINISH discoverSendTargets error=Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate wit
h target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])" from=::ff
ff:10.35.161.181,44070, flow_id=bcde9994-60e1-45a4-b8b3-68ac5197c383, task_id=6ba5b6b1-6a1b-40ad-b067-9a3629bf943a (api:50)
2018-08-07 14:09:48,469+0300 ERROR (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') Unexpected error (task:875)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run
    return fn(*args, **kargs)
  File "<string>", line 2, in discoverSendTargets
  File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 2957, in discoverSendTargets
    raise se.iSCSIDiscoveryError(portal, e)
iSCSIDiscoveryError: Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], ['iscsiadm: Login failed to authenticate with target ', 'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization', 'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure'])"
2018-08-07 14:09:48,469+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') Task._run: 6ba5b6b1-6a1b-40ad-b067-9a3629bf943a ({'ipv6_enabled': False, 'connection': u'10.35.83.188', 'password': '********', 'port': u'3260', 'user': u'admin'},) {} failed - stopping task (task:894)
2018-08-07 14:09:48,470+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') stopping in state failed (force False) (task:1256)
2018-08-07 14:09:48,470+0300 DEBUG (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') ref 1 aborting True (task:1002)
2018-08-07 14:09:48,470+0300 INFO  (jsonrpc/7) [storage.TaskManager.Task] (Task='6ba5b6b1-6a1b-40ad-b067-9a3629bf943a') aborting: Task is aborted: 'Failed discovery of iSCSI targets: u"portal=10.35.83.188:3260, err=(24, [], [\'iscsiadm: Login failed to authenticate with target \', \'iscsiadm: discovery login to 10.35.83.188 rejected: initiator failed authorization\', \'iscsiadm: Could not perform SendTargets discovery: iSCSI login failed due to authorization failure\'])"' - code 475 (task:1181)

Comment 39 Idan Shaby 2018-09-06 16:22:57 UTC

(In reply to Idan Shaby from comment #35)
> Hi,
> 
> I tried to discover + login to a target that requires authentication for
> both actions. I first made sure that I cannot do either without
> authenticating and then I tried to discover + login using:
> - master engine + master vdsm
> - 4.2 engine + 4.2 vdsm
> Both scenarios were successful, and the storage domain was created.
Update - Kevin ran the same test with a 4.1 engine + 4.2 vdsm, and it was successful.

To recap, we couldn't reproduce this bug, so I am closing it.
If you manage to reproduce, please reopen.