Bug 1134004 - [AAA] There is no information in log or in UI when various error during ldap search
Summary: [AAA] There is no information in log or in UI when various error during ldap ...
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: ovirt-engine-extension-aaa-ldap
Classification: oVirt
Component: Core
Version: 1.0.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: ---
Assignee: Alon Bar-Lev
QA Contact: Ondra Machacek
URL:
Whiteboard: infra
Depends On:
Blocks: oVirt-AAA-LDAP
TreeView+ depends on / blocked
 
Reported: 2014-08-26 15:40 UTC by Ondra Machacek
Modified: 2016-02-10 19:08 UTC (History)
11 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-09-16 10:35:49 UTC
oVirt Team: Infra
Embargoed:


Attachments (Terms of Use)
engine.log (30.69 KB, text/plain)
2014-09-10 18:48 UTC, Ondra Machacek
no flags Details
engine debug log (88.76 KB, text/plain)
2014-09-10 19:06 UTC, Ondra Machacek
no flags Details

Description Ondra Machacek 2014-08-26 15:40:38 UTC
Description of problem:


Version-Release number of selected component (if applicable):
ovirt-engine-3.5.0-0.0.master.20140821064931.gitb794d66.el6.noarch

How reproducible:
always

Steps to Reproduce:
1. configure OpenLDAP which don't support anonymous bind.

dn: olcDatabase={2}hdb,cn=config
add: olcRequires
olcRequires: authc

2. configure external ldap provider to use this openldap with anonymous bind
3. Try to search users in this OpenLDAP

Actual results:
No information in UI, REST even in engine log.

Expected results:
Tell user what's wrong.

Additional info:

slapd.log

Aug 26 17:39:21 localhost slapd[3819]: conn=1385 op=1 SRCH base="dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 deref=0 filter="(&(objectClass=uidObject)(uid=*)(|(givenName=*)(sn=*)(displayName=*)(uid=*)))"
Aug 26 17:39:21 localhost slapd[3819]: conn=1385 op=1 SRCH attr=entryUUID uid displayName memberOf department givenName sn title mail
Aug 26 17:39:21 localhost slapd[3819]: conn=1385 op=1 SEARCH RESULT tag=101 err=53 nentries=0 text=authentication required
Aug 26 17:39:21 localhost slapd[3819]: conn=1380 op=1 SRCH base="dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com" scope=2 deref=0 filter="(&(objectClass=groupOfNames)(|(cn=*)))"
Aug 26 17:39:21 localhost slapd[3819]: conn=1380 op=1 SRCH attr=entryUUID cn description memberOf
Aug 26 17:39:21 localhost slapd[3819]: conn=1380 op=1 SEARCH RESULT tag=101 err=53 nentries=0 text=authentication required

Comment 1 Ondra Machacek 2014-08-26 16:36:34 UTC
Same for other ldap vendors.

Comment 2 Ondra Machacek 2014-08-26 16:49:23 UTC
rhds/389ds is fine. message "Anonymous access is not allowed" is shown.

Comment 3 Oved Ourfali 2014-08-27 07:10:24 UTC
Yair - do we have this information to show the user?

Comment 4 Alon Bar-Lev 2014-08-27 17:54:04 UTC
misconfiguration of extension with mismatch of infrastructure settings is incorrect, ui is not the place to show such errors.

the provider will do whatever it can to fetch as many results as possible, ignoring any error of reachability/ssl/referrals/authentication, worse case scenario is return of empty results.

errors if exists will be available at engine log.

unless more input will close this as wontfix

Comment 5 Ondra Machacek 2014-09-10 06:48:48 UTC
[root@brq-openldap ~]# ldapsearch -LLL -x -b "dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com"
Server is unwilling to perform (53)
Additional information: authentication required

OpenLDAp return err 53.

in engine log, there is no information:

2014-09-10 06:46:53,235 TRACE [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) START, ValidateSessionQuery(refresh: true, filtered: false), log id: 657ea6aa
2014-09-10 06:46:53,235 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) Calling ValidateSession
2014-09-10 06:46:53,235 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) Input session ID is: a8b6b6c7-d0b8-4ac2-b626-f778434b8613
2014-09-10 06:46:53,235 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) Found session user
2014-09-10 06:46:53,235 DEBUG [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) ValidateSession ended
2014-09-10 06:46:53,235 TRACE [org.ovirt.engine.core.bll.aaa.ValidateSessionQuery] (ajp-/127.0.0.1:8702-2) FINISH, ValidateSessionQuery, log id: 657ea6aa
2014-09-10 06:46:53,238 TRACE [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) START, SearchQuery(search type: DirectoryUser, search pattern: [ADUSER@ldap-authz-openldap_brq-openldap:dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com: allnames=*], case sensitive: true [from: 0, max: -1] refresh: true, filtered: false), log id: 252cfeea
2014-09-10 06:46:53,238 DEBUG [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) ResourceManager::searchBusinessObjects(ADUSER@ldap-authz-openldap_brq-openldap:dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com: allnames=*) - entered
2014-09-10 06:46:53,254 TRACE [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) FINISH, SearchQuery, log id: 252cfeea
2014-09-10 06:46:53,254 TRACE [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) START, SearchQuery(search type: DirectoryGroup, search pattern: [ADGROUP@ldap-authz-openldap_brq-openldap:dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com: name=*], case sensitive: true [from: 0, max: -1] refresh: true, filtered: false), log id: 53579b05
2014-09-10 06:46:53,254 DEBUG [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) ResourceManager::searchBusinessObjects(ADGROUP@ldap-authz-openldap_brq-openldap:dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com: name=*) - entered
2014-09-10 06:46:53,263 TRACE [org.ovirt.engine.core.bll.SearchQuery] (ajp-/127.0.0.1:8702-2) FINISH, SearchQuery, log id: 53579b05

Comment 6 Alon Bar-Lev 2014-09-10 10:34:47 UTC
you probably got an error error before something like:

2014-09-10 13:34:05,451 INFO  [org.ovirt.engineextensions.aaa.ldap.Framework] (MSC service thread 1-3) Creating LDAP pool 'authn' for 'ldap-authn-rhds_brq-ldap'
2014-09-10 13:34:06,296 ERROR [org.ovirt.engineextensions.aaa.ldap.AuthnExtension] (MSC service thread 1-3) Cannot initialize LDAP framework, deferring initialization. Error: Anonymous access is not allowed

Comment 7 Ondra Machacek 2014-09-10 18:48:03 UTC
Created attachment 936283 [details]
engine.log

Not really, please check attachment.

Comment 8 Alon Bar-Lev 2014-09-10 18:54:01 UTC
Poll creation succeeded, so authentication succeeded. If you provide debug I can see what's going on.

2014-09-10 18:34:07,724 INFO  [org.ovirt.engineextensions.aaa.ldap.Framework] (ServerService Thread Pool -- 51) Creating LDAP pool 'authz' for 'ldap-authz-openldap_brq-openldap'
2014-09-10 18:34:07,790 INFO  [org.ovirt.engine.core.extensions.mgr.ExtensionsManager] (ServerService Thread Pool -- 51) Extension 'ldap-authz-openldap_brq-openldap' initialized

With your configuration I got comment#6 at my setup.

Comment 9 Ondra Machacek 2014-09-10 18:59:28 UTC
Do you use OpenLDAP or RHDS?

With rhds I got the error too, but with OpenLDAP no.

I am using this configuration:

pool.default.serverset.single.server = brq-openldap.rhev.lab.eng.brq.redhat.com
pool.default.auth.type = none

I will send debug log.

Comment 10 Ondra Machacek 2014-09-10 19:06:02 UTC
Created attachment 936286 [details]
engine debug log

Comment 11 Alon Bar-Lev 2014-09-10 19:14:00 UTC
Authentication succeeded, root dse obtained.

2014-09-10 18:49:37,814 DEBUG [org.ovirt.engineextensions.aaa.ldap.Framework] (ServerService Thread Pool -- 45) Return RootDSE: [Attribute(name=objectClass, values={'top', 'OpenLDAProotDSE'}), Attribute(name=structuralObjectClass, values={'OpenLDAProotDSE'}), Attribute(name=configContext, values={'cn=config'}), Attribute(name=monitorContext, values={'cn=Monitor'}), Attribute(name=namingContexts, values={'dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com'}), Attribute(name=supportedControl, values={'2.16.840.1.113730.3.4.18', '2.16.840.1.113730.3.4.2', '1.3.6.1.4.1.4203.1.10.1', '1.2.840.113556.1.4.319', '1.2.826.0.1.3344810.2.3', '1.3.6.1.1.13.2', '1.3.6.1.1.13.1', '1.3.6.1.1.12'}), Attribute(name=supportedExtension, values={'1.3.6.1.4.1.1466.20037', '1.3.6.1.4.1.4203.1.11.1', '1.3.6.1.4.1.4203.1.11.3', '1.3.6.1.1.8'}), Attribute(name=supportedFeatures, values={'1.3.6.1.1.14', '1.3.6.1.4.1.4203.1.5.1', '1.3.6.1.4.1.4203.1.5.2', '1.3.6.1.4.1.4203.1.5.3', '1.3.6.1.4.1.4203.1.5.4', '1.3.6.1.4.1.4203.1.5.5'}), Attribute(name=supportedLDAPVersion, values={'3'}), Attribute(name=supportedSASLMechanisms, values={'CRAM-MD5', 'NTLM', 'DIGEST-MD5', 'GSSAPI'}), Attribute(name=entryDN, values={''}), Attribute(name=subschemaSubentry, values={'cn=Subschema'})]

2014-09-10 18:49:37,840 DEBUG [org.ovirt.engineextensions.aaa.ldap.Framework] (ServerService Thread Pool -- 45) Return RootDSE: [Attribute(name=objectClass, values={'top', 'OpenLDAProotDSE'}), Attribute(name=structuralObjectClass, values={'OpenLDAProotDSE'}), Attribute(name=configContext, values={'cn=config'}), Attribute(name=monitorContext, values={'cn=Monitor'}), Attribute(name=namingContexts, values={'dc=brq-openldap,dc=rhev,dc=lab,dc=eng,dc=brq,dc=redhat,dc=com'}), Attribute(name=supportedControl, values={'2.16.840.1.113730.3.4.18', '2.16.840.1.113730.3.4.2', '1.3.6.1.4.1.4203.1.10.1', '1.2.840.113556.1.4.319', '1.2.826.0.1.3344810.2.3', '1.3.6.1.1.13.2', '1.3.6.1.1.13.1', '1.3.6.1.1.12'}), Attribute(name=supportedExtension, values={'1.3.6.1.4.1.1466.20037', '1.3.6.1.4.1.4203.1.11.1', '1.3.6.1.4.1.4203.1.11.3', '1.3.6.1.1.8'}), Attribute(name=supportedFeatures, values={'1.3.6.1.1.14', '1.3.6.1.4.1.4203.1.5.1', '1.3.6.1.4.1.4203.1.5.2', '1.3.6.1.4.1.4203.1.5.3', '1.3.6.1.4.1.4203.1.5.4', '1.3.6.1.4.1.4203.1.5.5'}), Attribute(name=supportedLDAPVersion, values={'3'}), Attribute(name=supportedSASLMechanisms, values={'CRAM-MD5', 'NTLM', 'DIGEST-MD5', 'GSSAPI'}), Attribute(name=entryDN, values={''}), Attribute(name=subschemaSubentry, values={'cn=Subschema'})]

Comment 12 Ondra Machacek 2014-09-10 19:45:19 UTC
Root dse could be obtained also for AD by default with anonymous bind.
It fails when obtaining other values, and user knows, with OpenLDAP he doesn't.

Comment 13 Alon Bar-Lev 2014-09-10 19:50:25 UTC
if search returns nothing, then nothing is returned in this configuration. again, we are not protecting sysadmin from himself.
I do not see any error at ldap level.

Comment 14 Yair Zaslavsky 2014-09-15 07:52:10 UTC
Alon, I still think that some fixes should be made here, maybe not in the input ondra gave.
For example, if you look at AuthzUtils.fetchPrincipalRecord, Authz status codes are not propgated anywhere to UI.
Wouldn't you want at least to show some human readable text at UI for these status codes?
(Same for authn I assume).

Comment 15 Alon Bar-Lev 2014-09-15 08:02:52 UTC
fetchPrincipalRecord is not per search, and every exception you get is visible in ui and in log. well, we kept ui "generic" messages of previous version.

for the search we survive much of the failure, but every error from extension is visible in log.

in this particular case there was no error even from extension point of view.

Comment 16 Yair Zaslavsky 2014-09-15 11:08:49 UTC
(In reply to Alon Bar-Lev from comment #15)
> fetchPrincipalRecord is not per search, and every exception you get is
> visible in ui and in log. well, we kept ui "generic" messages of previous
> version.

True, but when login fails, don't you want an informative mesaage at UI on why it failed?

> 
> for the search we survive much of the failure, but every error from
> extension is visible in log.
> 
> in this particular case there was no error even from extension point of view.

Comment 17 Alon Bar-Lev 2014-09-15 11:14:38 UTC
(In reply to Yair Zaslavsky from comment #16)
> (In reply to Alon Bar-Lev from comment #15)
> > fetchPrincipalRecord is not per search, and every exception you get is
> > visible in ui and in log. well, we kept ui "generic" messages of previous
> > version.
> 
> True, but when login fails, don't you want an informative mesaage at UI on
> why it failed?

there was no failure in login, the rootdse in this specific case access was a success, ldap session is established.

Comment 18 Ondra Machacek 2014-09-16 10:35:49 UTC
In this case rootdse could be obtained for anonymous, so no error on output.
If root dse is not available for anonymous bind, exception occur an user can
see what's wrong. Closing as not a bug as it is expected behavior.


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