Grouper Users - Open Discussion List

[Baron Fujimoto <>]

It apepars that the details detailed on the "vt-ldap was converted to 
Ldaptive"[*] page have been done with the requisite changes to 
subject.properties and grouper-loader.properties handled by the 
grouperInstaller update or my subsequent modifications. The page does mention 
that "The default pooling validator is SearchValidator.  And the validation 
is done on connection checkout by default.  ConnectLdapValidator is no longer 
valid." I have not set any values for this so it is presumably using defaults 
from grouper-loader.base.properties. Based on the the exception stack trace, 
the immediate problem seems to been validation related.

Caused by: [org.ldaptive.pool.ValidationException@104803851::resultCode=null, 
matchedDn=null, responseControls=null, referralURLs=null, messageId=-1, 
message=Validation of connection failed, providerException=null]

The upgrade instructions page also suggests using the "Grouper subject API 
diagnostics in UI" to confirm the configuration. I had not yet tried 
upgrading the UI, presuming that getting a working API was a reasonable 
prerequisite. However, when I try to upgrade the UI with the grouperInstaller 
I can't seem to find the right location to point it at. If I point it at 
where I would previously rebuild the UI via "ant war" it reports it "Cant 
find Grouper UI properties files or libs".

So I still seem to be stuck at the same place. Can I troubleshoot further 
without the API diagnostics in the UI?

[*] 
<https://spaces.at.internet2.edu/display/Grouper/vt-ldap+to+ldaptive+migration+for+LDAP+access>

On Fri, Jul 05, 2019 at 07:38:34PM +0000, Hyzer, Chris wrote:
>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

-- 
Baron Fujimoto <> :: UH Information Technology Services
minutas cantorum, minutas balorum, minutas carboratum desendus pantorum