Grouper Users - Open Discussion List

["Hyzer, Chris" <>]

Did you do this?

https://spaces.at.internet2.edu/display/Grouper/v2.4+Upgrade+Instructions+from+v2.3

the vt-ldap to ldaptive

-----Original Message-----
From:  
<> On Behalf Of Baron Fujimoto
Sent: Wednesday, July 03, 2019 5:45 PM
To: Grouper Users <>
Subject: [grouper-users] grouper upgrade 2.2.2 to 2.4.0: Problem with ldap 
connection

I'm attempting to upgrade grouper 2.2.2 to 2.4.0 using grouperInstaller. I'm 
currently stuck though with some aspect of the converted configs. When I 
first tried to run gsh, I encountered the following error:

=====
Subject API error: error with subject source id: UH_core_LDAP, name: UH_LDAP, 
problem with getSubject by id, in subject.properties: search searchSubject: , 
edu.internet2.middleware.subject.SourceUnavailableException: Ldap Exception: 
Missing property subjectApi.source.UH_core_LDAP.param.ldapServerId.value in 
subject.properties.  The value of this property should point to your LDAP 
configuration in the grouper-loader.properties file. e.g. if your 
grouper-loader.properties has ldap.personLdap.url, then the value of this 
property would be personLdap
=====

This appeared to be resolved by adding the following to subject.properties as 
suggested:

subjectApi.source.UH_core_LDAP.param.ldapServerId.value = personLdap

However, now when I start gsh, I get:

=====
$ ./gsh
Detected Grouper directory structure 'api' (valid is api or webapp)
Using GROUPER_HOME:           
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4
Using GROUPER_CONF:           
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf
Using JAVA:                   /usr/java/latest/bin/java
Using CLASSPATH:              
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/dist/lib/grouper.jar:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/lib/grouper/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/lib/custom/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/lib/jdbcSamples/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/lib/ant/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/lib/test/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/dist/lib/test/*:/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/src/resources
using MEMORY:                 64m-750m
Grouper starting up: version: 2.4.0, build date: null, env: grouper-dev
grouperPatchStatus read from: 
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/grouperPatchStatus.properties
api patches installed:        0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 
14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 
33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 
52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64
grouper.properties read from: 
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf/grouper.properties
Grouper current directory is: 
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/bin
log4j.properties read from:   
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf/log4j.properties
Grouper is logging to file:   
/home/grouper/grouper/logs/grouper-api_error.log, at min level WARN for 
package: edu.internet2.middleware.grouper, based on log4j.properties
grouper.hibernate.properties: 
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf/grouper.hibernate.properties
grouper.hibernate.properties: 
grouper@jdbc:mysql://grouper.example.edu:3306/grprdev?CharSet=utf8&useUnicode=true&characterEncoding=utf8&useSSL=false
subject.properties read from: 
/home/grouper/grouper/grouper.apiBinary-2.2.2-upgrade-to-2.4/conf/subject.properties
sources configured in:        subject.properties
subject.properties groupersource id: g:gsa
subject.properties groupersource id: grouperEntities
subject.properties ldap source id:   UH core LDAP: personLdap
Subject API error: error with subject source id: UH core LDAP, name: UH LDAP, 
problem with getSubject by id, in subject.properties: search searchSubject: , 
edu.internet2.middleware.subject.SourceUnavailableException: Ldap Exception: 
Problem with ldap conection: personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:541)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResults(LdapSourceAdapter.java:433)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapUnique(LdapSourceAdapter.java:562)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getSubject(LdapSourceAdapter.java:189)
    at 
edu.internet2.middleware.subject.SubjectCheckConfig.checkConfig(SubjectCheckConfig.java:114)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig$1.callback(GrouperCheckConfig.java:530)
    at 
edu.internet2.middleware.grouper.GrouperSession.callbackGrouperSession(GrouperSession.java:974)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig.checkConfig(GrouperCheckConfig.java:526)
    at 
edu.internet2.middleware.grouper.misc.GrouperStartup.startup(GrouperStartup.java:313)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShell.main(GrouperShell.java:165)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShellWrapper.main(GrouperShellWrapper.java:31)
Caused by: java.lang.RuntimeException: Problem with ldap conection: 
personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:381)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.list(LdaptiveSessionImpl.java:601)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:538)
    ... 10 more
Caused by: [org.ldaptive.pool.ValidationException@104803851::resultCode=null, 
matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, 
message=Validation of connection failed, providerException=null]
    at 
org.ldaptive.pool.AbstractConnectionPool.activateAndValidateConnection(AbstractConnectionPool.java:671)
    at 
org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:150)
    at 
org.ldaptive.pool.PooledConnectionFactory.getConnection(PooledConnectionFactory.java:68)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:365)
    ... 12 more

Couldnt startup grouper: error with subject source id: UH core LDAP, name: UH 
LDAP, problem with getSubject by id, in subject.properties: search 
searchSubject:
java.lang.RuntimeException: error with subject source id: UH core LDAP, name: 
UH LDAP, problem with getSubject by id, in subject.properties: search 
searchSubject:
    at 
edu.internet2.middleware.subject.SubjectCheckConfig.checkConfig(SubjectCheckConfig.java:122)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig$1.callback(GrouperCheckConfig.java:530)
    at 
edu.internet2.middleware.grouper.GrouperSession.callbackGrouperSession(GrouperSession.java:974)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig.checkConfig(GrouperCheckConfig.java:526)
    at 
edu.internet2.middleware.grouper.misc.GrouperStartup.startup(GrouperStartup.java:313)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShell.main(GrouperShell.java:165)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShellWrapper.main(GrouperShellWrapper.java:31)
Caused by: edu.internet2.middleware.subject.SourceUnavailableException: Ldap 
Exception: Problem with ldap conection: personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:541)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResults(LdapSourceAdapter.java:433)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapUnique(LdapSourceAdapter.java:562)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getSubject(LdapSourceAdapter.java:189)
    at 
edu.internet2.middleware.subject.SubjectCheckConfig.checkConfig(SubjectCheckConfig.java:114)
    ... 6 more
Caused by: java.lang.RuntimeException: Problem with ldap conection: 
personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:381)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.list(LdaptiveSessionImpl.java:601)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:538)
    ... 10 more
Caused by: [org.ldaptive.pool.ValidationException@104803851::resultCode=null, 
matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, 
message=Validation of connection failed, providerException=null]
    at 
org.ldaptive.pool.AbstractConnectionPool.activateAndValidateConnection(AbstractConnectionPool.java:671)
    at 
org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:150)
    at 
org.ldaptive.pool.PooledConnectionFactory.getConnection(PooledConnectionFactory.java:68)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:365)
    ... 12 more
Exception in thread "main" java.lang.RuntimeException: error with subject 
source id: UH core LDAP, name: UH LDAP, problem with getSubject by id, in 
subject.properties: search searchSubject:
    at 
edu.internet2.middleware.subject.SubjectCheckConfig.checkConfig(SubjectCheckConfig.java:122)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig$1.callback(GrouperCheckConfig.java:530)
    at 
edu.internet2.middleware.grouper.GrouperSession.callbackGrouperSession(GrouperSession.java:974)
    at 
edu.internet2.middleware.grouper.misc.GrouperCheckConfig.checkConfig(GrouperCheckConfig.java:526)
    at 
edu.internet2.middleware.grouper.misc.GrouperStartup.startup(GrouperStartup.java:313)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShell.main(GrouperShell.java:165)
    at 
edu.internet2.middleware.grouper.app.gsh.GrouperShellWrapper.main(GrouperShellWrapper.java:31)
Caused by: edu.internet2.middleware.subject.SourceUnavailableException: Ldap 
Exception: Problem with ldap conection: personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:541)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResults(LdapSourceAdapter.java:433)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapUnique(LdapSourceAdapter.java:562)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getSubject(LdapSourceAdapter.java:189)
    at 
edu.internet2.middleware.subject.SubjectCheckConfig.checkConfig(SubjectCheckConfig.java:114)
    ... 6 more
Caused by: java.lang.RuntimeException: Problem with ldap conection: 
personLdap,
Error querying ldap server id: personLdap, searchDn: dc=hawaii,dc=edu, 
filter: '(& (uhuuid=grouperTestSubjectByIdOnStartupASDFGHJ) 
(objectclass=uhEduPerson))', returning attributes: 
[Ljava.lang.String;@6f5bd362
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:381)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.list(LdaptiveSessionImpl.java:601)
    at 
edu.internet2.middleware.subject.provider.LdapSourceAdapter.getLdapResultsHelper(LdapSourceAdapter.java:538)
    ... 10 more
Caused by: [org.ldaptive.pool.ValidationException@104803851::resultCode=null, 
matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, 
message=Validation of connection failed, providerException=null]
    at 
org.ldaptive.pool.AbstractConnectionPool.activateAndValidateConnection(AbstractConnectionPool.java:671)
    at 
org.ldaptive.pool.BlockingConnectionPool.getConnection(BlockingConnectionPool.java:150)
    at 
org.ldaptive.pool.PooledConnectionFactory.getConnection(PooledConnectionFactory.java:68)
    at 
edu.internet2.middleware.grouper.ldap.ldaptive.LdaptiveSessionImpl.callbackLdapSession(LdaptiveSessionImpl.java:365)
    ... 12 more
=====

Looking at our LDAP logs, the only entries I find are the bind/unbind for our 
grouper dn, but no queries that might have part of a connection validation?

=====
[03/Jul/2019:11:27:27 -1000] conn=1521212 fd=203 slot=203 SSL connection from 
10.0.0.10 to 10.0.0.20
[03/Jul/2019:11:27:27 -1000] conn=1521212 TLS1.2 128-bit AES-GCM
[03/Jul/2019:11:27:27 -1000] conn=1521212 op=0 BIND 
dn="cn=foo,ou=bar,dc=hawaii,dc=edu" method=128 version=3
[03/Jul/2019:11:27:27 -1000] conn=1521212 op=0 RESULT err=0 tag=97 nentries=0 
etime=0 dn="cn=foo,ou=bar,dc=hawaii,dc=edu"
[03/Jul/2019:11:27:30 -1000] conn=1521212 op=1 SRCH base="dc=hawaii,dc=edu" 
scope=0 filter="(objectClass=*)" attrs="1.1"
[03/Jul/2019:11:27:30 -1000] conn=1521212 op=1 RESULT err=0 tag=101 
nentries=0 etime=0
[03/Jul/2019:11:27:30 -1000] conn=1521212 op=2 UNBIND
[03/Jul/2019:11:27:30 -1000] conn=1521212 op=2 fd=203 closed - U1

[03/Jul/2019:11:27:27 -1000] conn=1521213 fd=204 slot=204 SSL connection from 
10.0.0.10 to 10.0.0.20
[03/Jul/2019:11:27:27 -1000] conn=1521213 TLS1.2 128-bit AES-GCM
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=0 BIND 
dn="cn=foo,ou=bar,dc=hawaii,dc=edu" method=128 version=3
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=0 RESULT err=0 tag=97 nentries=0 
etime=0 dn="cn=foo,ou=bar,dc=hawaii,dc=edu"
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=1 SRCH base="dc=hawaii,dc=edu" 
scope=0 filter="(objectClass=*)" attrs="1.1"
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=1 RESULT err=0 tag=101 
nentries=0 etime=0
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=2 UNBIND
[03/Jul/2019:11:27:27 -1000] conn=1521213 op=2 fd=204 closed - U1
=====

One thing I don't understand is that we weren't even binding with our grouper 
user's dn until I added the credentials to grouper-loader.properties. If the 
same credentials are only present in subject.properties, then we only see 
anonymous binds in our ldap logs. The properties in our subject properties 
look like:

subjectApi.source.UH_core_LDAP.id = UH core LDAP
[...]
subjectApi.source.UH_core_LDAP.param.SECURITY_PRINCIPAL.value = 
cn=foo,ou=bar,dc=hawaii,dc=edu
subjectApi.source.UH_core_LDAP.param.SECURITY_CREDENTIALS.value = *secret*

=====
[03/Jul/2019:11:31:08 -1000] conn=1521409 fd=210 slot=210 SSL connection from 
10.0.0.10 to 10.0.0.20
[03/Jul/2019:11:31:08 -1000] conn=1521409 TLS1.2 128-bit AES-GCM
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=0 BIND dn="" method=128 version=3
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=0 RESULT err=0 tag=97 nentries=0 
etime=0 dn=""
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=1 SRCH base="dc=hawaii,dc=edu" 
scope=0 filter="(objectClass=*)" attrs="1.1"
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=1 RESULT err=0 tag=101 
nentries=0 etime=0
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=2 UNBIND
[03/Jul/2019:11:31:08 -1000] conn=1521409 op=2 fd=210 closed - U1

[03/Jul/2019:11:31:08 -1000] conn=1521410 fd=208 slot=208 SSL connection from 
10.0.0.10 to 10.0.0.20
[03/Jul/2019:11:31:08 -1000] conn=1521410 TLS1.2 128-bit AES-GCM
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=0 BIND dn="" method=128 version=3
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=0 RESULT err=0 tag=97 nentries=0 
etime=0 dn=""
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=1 SRCH base="dc=hawaii,dc=edu" 
scope=0 filter="(objectClass=*)" attrs="1.1"
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=1 RESULT err=0 tag=101 
nentries=0 etime=0
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=2 UNBIND
[03/Jul/2019:11:31:08 -1000] conn=1521410 op=2 fd=208 closed - U1
=====

Any ideas or suggestions would be appreciated.

* Minor typo, but stack trace exception says "Problem with ldap conection", 
should presumably be "connection".
-- 
Baron Fujimoto <> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum