Grouper Users - Open Discussion List

["Guenther, Dean R." <>]

Hi Chris, I’m attaching the grouper log. Did I get all of the DEBUG statements added to give you the logging you needed?

 

 

Command I sent was the same:

 

edu.internet2.middleware.grouper.ldap.LdapSession.list(String.class, "pspng_activedirectory","OU=NIDs,OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu",LdapSearchScope.SUBTREE_SCOPE,"(cn=guenther)","cn")

 

 

 

 

 

 

Dean Guenther                          
Washington State University    Phone:    509 335-0433
Pullman, WA. 99164-1222        fax:      509 335-0540
Identity and Access Management Manager

 

 

From: "Hyzer, Chris" <>
Date: Sunday, June 17, 2018 at 7:10 PM
To: "" <>, "" <>
Subject: RE: [grouper-users] PSPNG problem accessing group info in AD

 

This line:

 

2018-06-03 16:08:01,780: [pspng_activedirectory-FullSync-Thread] ERROR Provisioner.prepareGroupCache(736) -  - Problem fetching information on group 'test:ref:employee:hourly.appointed'

 

 

Should have a stacktrace after it.  Are you sending the whole log?  Can you stop the loader.  delete the file.  Start the loader. reproduce the error.  And send the entire log file please?

 

From: Guenther, Dean R. [mailto:]
Sent: Friday, June 15, 2018 1:01 PM
To: Hyzer, Chris <>;
Subject: RE: [grouper-users] PSPNG problem accessing group info in AD

 

Hi Chris, Bert,

 

I can’t say for certain whether the loader is having a problem or PSPNG. But I think its PSPNG because of this error:

 

2018-06-03 16:08:01,780: [pspng_activedirectory-FullSync-Thread] ERROR Provisioner.prepareGroupCache(736) -  - Problem fetching information on group 'test:ref:employee:hourly.appointed'

 

I’ve tried with both the group created in AD and not pre-existing in AD.  My userSearch* config is:

 

changeLog.consumer.pspng_activedirectory.userSearchBaseDn = ou=NIDs,ou=WSU Accounts,dc=tempad,dc=wsu,dc=edu

changeLog.consumer.pspng_activedirectory.userSearchFilter = wsuExternalSystemID=${subject.id}

changeLog.consumer.pspng_activedirectory.userSearchAttributes = dn,cn,userprincipalname,wsuexternalsystemid,objectclass

 

Here is the output from GSH

 

groovy:000> edu.internet2.middleware.grouper.ldap.LdapSession.list(String.class, "pspng_activedirectory","OU=NIDs,OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu",LdapSearchScope.SUBTREE_SCOPE,"(cn=guenther)","cn")

ERROR java.lang.RuntimeException:

Problem with ldap conection: pspng_activedirectory,

Error querying ldap server id: pspng_activedirectory, searchDn: OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu, filter: '(cn=guenther)', returning attribute: cn

        at edu.internet2.middleware.grouper.ldap.LdapSession.callbackLdapSession (LdapSession.java:249)

        at edu.internet2.middleware.grouper.ldap.LdapSession.list (LdapSession.java:276)

        at edu.internet2.middleware.grouper.ldap.LdapSession$list.call (Unknown Source)

 

I also repeated the gsh command with the filter “(wsuExternalSystemID=9099798451)” and it was essentially the same.

I also tried the path of both “OU=NIDs,OU=WSU Accounts” and the broader “OU=WSU Accounts”. As expected that was the same too.

 

And here is the output from the log:

 

2018-06-15 09:42:55,863: [main] DEBUG GrouperLoaderConfig.retrieveLdapProfile(319) -  - LDAP config for server id: pspng_activedirectory: GrouperLoaderLdapServer [batchSize=-1, configFileFromClasspath: , countLimit=-1, driver=null, expirationTime=-1, maxPoolSize=-1, minPoolSize=-1, pagedResultsSize=1000, pass=XXXXX, pruneTimerPeriod=-1, referral=follow, saslAuthorizationId=null, saslRealm=null, timeLimit=-1, timeout=-1, tls=false, url="ldaps://temp-dc01-pul.tempad.wsu.edu:636/dc=tempad,dc=wsu,dc=edu," user=cn=grouper.writer,ou=service accounts,ou=wsu accounts,dc=tempad,dc=wsu,dc=edu, validateOnCheckIn=false, validateOnCheckOut=true, validatePeriodically=false, validateTimerPeriod=-1, searchResultHandlers=[Ledu.vt.middleware.ldap.handler.SearchResultHandler;@4ccf31e5]

2018-06-15 09:42:55,916: [main] DEBUG LdapSession.callbackLdapSession(228) -  - pre-checkout: ldap id: pspng_activedirectory, pool active: 0, available: 0

2018-06-15 09:42:55,918: [main] DEBUG DefaultConnectionHandler.connectInternal(74) -  - Bind with the following parameters:

2018-06-15 09:42:55,919: [main] DEBUG DefaultConnectionHandler.connectInternal(75) -  -   authtype = simple

2018-06-15 09:42:55,919: [main] DEBUG DefaultConnectionHandler.connectInternal(76) -  -   dn = cn=grouper.writer,ou=service accounts,ou=wsu accounts,dc=tempad,dc=wsu,dc=edu

2018-06-15 09:42:55,919: [main] DEBUG DefaultConnectionHandler.connectInternal(83) -  -   credential = <suppressed>

2018-06-15 09:42:56,185: [main] DEBUG DefaultConnectionHandler.connectInternal(128) -  - Set hostname verifier for ldaps

2018-06-15 09:42:56,365: [main] DEBUG AggregateTrustManager.checkServerTrusted(75) -  - invoking checkServerTrusted for

2018-06-15 09:42:56,470: [main] DEBUG AggregateTrustManager.checkServerTrusted(75) -  - invoking checkServerTrusted for

2018-06-15 09:42:56,470: [main] DEBUG DefaultHostnameVerifier.verify(127) -  - Verify with the following parameters:

2018-06-15 09:42:56,470: [main] DEBUG DefaultHostnameVerifier.verify(128) -  -   hostname = temp-dc01-pul.tempad.wsu.edu

2018-06-15 09:42:56,471: [main] DEBUG DefaultHostnameVerifier.verify(129) -  -   cert = CN=temp-dc01-pul.tempad.wsu.edu, OU=SYS, O=Washington State University, STREET=362 Johnson Tower, L=Pullman, ST=Washington, OID.2.5.4.17=99164, C=US

2018-06-15 09:42:56,473: [main] DEBUG DefaultHostnameVerifier.verifyDNS(202) -  - verifyDNS using subjectAltNames = [temp-dc01-pul.tempad.wsu.edu]

2018-06-15 09:42:56,473: [main] DEBUG DefaultHostnameVerifier.verifyDNS(210) -  - verifyDNS found hostname match: temp-dc01-pul.tempad.wsu.edu

2018-06-15 09:42:56,473: [main] DEBUG AggregateTrustManager.getAcceptedIssuers(90) -  - invoking getAcceptedIssuers invoked for

2018-06-15 09:42:56,474: [main] DEBUG AggregateTrustManager.getAcceptedIssuers(90) -  - invoking getAcceptedIssuers invoked for

2018-06-15 09:42:56,545: [main] WARN  AbstractLdapFactory.validate(165) -  - validate called, but no validator configured

2018-06-15 09:42:56,545: [main] DEBUG LdapSession.callbackLdapSession(234) -  - post-checkout: ldap id: pspng_activedirectory, pool active: 1, available: 0

2018-06-15 09:42:56,547: [main] DEBUG AbstractLdap.pagedSearch(290) -  - Paginated search with the following parameters:

2018-06-15 09:42:56,547: [main] DEBUG AbstractLdap.pagedSearch(291) -  -   dn = OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu

2018-06-15 09:42:56,548: [main] DEBUG AbstractLdap.pagedSearch(292) -  -   filter = (cn=guenther)

2018-06-15 09:42:56,548: [main] DEBUG AbstractLdap.pagedSearch(293) -  -   filterArgs = []

2018-06-15 09:42:56,548: [main] DEBUG AbstractLdap.pagedSearch(294) -  -   searchControls =

2018-06-15 09:42:56,549: [main] DEBUG AbstractLdap.pagedSearch(295) -  -   handler = [edu.vt.middleware.ldap.handler.FqdnSearchResultHandler@15b7c582, , , ]

2018-06-15 09:42:56,561: [main] DEBUG GrouperClientLog.debug(92) -  - Cant find text for variable: 'newline'

2018-06-15 09:42:56,562: [main] DEBUG GrouperClientLog.debug(92) -  - Cant find text for variable: 'newline'

2018-06-15 09:42:56,562: [main] DEBUG GrouperClientLog.debug(92) -  - needToCheckIfFilesNeedReloading: true, needToCheckIfFilesNeedReloading2: true, configObjectPropertyCount: 269

 

From: Hyzer, Chris []
Sent: Friday, June 15, 2018 8:42 AM
To: Guenther, Dean R. <>;
Subject: RE: [grouper-users] PSPNG problem accessing group info in AD

 

Bert, can you please look at this?

 

The “loader” pulls things from AD, and the “pspng” pushes things to AD.  You are asking about the pspng right?

 

In my example online that I think you have seen I used:

 

changeLog.consumer.pspng_activedirectory.userSearchBaseDn = DC=kite-dev,DC=upenn,DC=edu

changeLog.consumer.pspng_activedirectory.userSearchFilter = employeeID=${subject.id}

changeLog.consumer.pspng_activedirectory.userSearchAttributes = dn,cn,uid,mail,samAccountName, uidNumber,objectclass,employeeID

 

Do you have a similar configuration?  You need to tell grouper how to find subjects and resolve subjects from AD.

 

For this one, please include the output from GSH and the full log for that command:

 

groovy:000> edu.internet2.middleware.grouper.ldap.LdapSession.list(String.class, "pspng_activedirectory","OU=WSU

 

 

 

From: [] On Behalf Of Guenther, Dean R.
Sent: Thursday, June 14, 2018 11:37 AM
To:
Subject: Re: [grouper-users] Loader problem accessing group info in AD

 

I hadn’t a response from anybody on this post yet so I thought I’d poke the thread. The error says “problem fetching information on group”. Is it having a problem fetching info from AD?

thanks – Dean

 

 

 

 

Dean Guenther                          
Washington State University    Phone:    509 335-0433
Pullman, WA. 99164-1222        fax:      509 335-0540
Identity and Access Management Manager

 

 

From: <> on behalf of "" <>
Date: Monday, June 4, 2018 at 12:14 PM
To: "" <>
Subject: [grouper-users] Loader problem accessing group info in AD

 

I’ve built a group in AD that I want to provision members to called “test:ref:employee:hourly.appointed”. When the loader attempts to provision it complains that it cannot fetch information on the group:

 

2018-06-03 16:08:01,780: [pspng_activedirectory-FullSync-Thread] ERROR Provisioner.evaluateJexlExpression(556) -  - Jexl _expression_ null could not be evaluated for subject 'null/null' and group 'test:ref:employee:hourly.appointed/null' which used variableMap '{idIndex=10095, userSearchBaseDn=ou=NIDs,ou=WSU Accounts,dc=tempad,dc=wsu,dc=edu, groupAttributes={etc:pspng:provision_to=[pspng_activedirectory]}, groupCreationBaseDn=ou=grouper groups,ou=provisioned groups,ou=enterprise groups,ou=wsu authorization groups,dc=tempad,dc=wsu,dc=edu, stemAttributes={}, , groupSearchBaseDn=ou=grouper groups,ou=provisioned groups,ou=enterprise groups,ou=wsu authorization groups,dc=tempad,dc=wsu,dc=edu, name=test:ref:employee:hourly.appointed, provisionerName=pspng_activedirectory, group=Group[name=test:ref:employee:hourly.appointed,uuid=d4395181f7214efda1be4a8b568ece5d], provisionerType=LdapGroupProvisioner}'

2018-06-03 16:08:01,780: [pspng_activedirectory-FullSync-Thread] ERROR Provisioner.prepareGroupCache(736) -  - Problem fetching information on group 'test:ref:employee:hourly.appointed'

 

I’m not certain what info the loader is trying to fetch. I am able to do an ldapsearch of the group houly.appointed without any problem from the same host where the loader lives. So it seems the group is readable. Then I thought I’d try using LdapSession.list within gsh on a user object and that also gave an error:

 

groovy:000> edu.internet2.middleware.grouper.ldap.LdapSession.list(String.class, "pspng_activedirectory","OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu",LdapSearchScope.SUBTREE_SCOPE,"(cn=guenther)","cn");

ERROR java.lang.RuntimeException:

Problem with ldap conection: pspng_activedirectory,

Error querying ldap server id: pspng_activedirectory, searchDn: OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu, filter: '(cn=guenther)', returning attribute: cn

        at edu.internet2.middleware.grouper.ldap.LdapSession.callbackLdapSession (LdapSession.java:249)

        at edu.internet2.middleware.grouper.ldap.LdapSession.list (LdapSession.java:276)

        at edu.internet2.middleware.grouper.ldap.LdapSession$list.call (Unknown Source)

 

But it does seem odd that it says “Unknown Source”. The ldap bind looks good. So I’m not certain why it thinks its an unknown source. In the log it shows this for the LdapSession.list:

 

2018-06-04 10:11:29,493: [main] DEBUG LdapSession.callbackLdapSession(228) -  - pre-checkout: ldap id: pspng_activedirectory, pool active: 0, available: 1

2018-06-04 10:11:29,494: [main] WARN  AbstractLdapFactory.validate(165) -  - validate called, but no validator configured

2018-06-04 10:11:29,494: [main] DEBUG HibernateSession.<init>(290) -  - grouperTransactionType: READONLY_OR_USE_EXISTING, okToUseHibernate: true, readonlyMode: false, parentSessionExists: true, newHibernateSession: false, hibernateSession: HibernateSession (4eb175a4): notNew, notReadonly, READ_WRITE_NEW, activeTransaction, session (7da056b2)

2018-06-04 10:11:29,494: [main] DEBUG LdapSession.callbackLdapSession(234) -  - post-checkout: ldap id: pspng_activedirectory, pool active: 1, available: 0

2018-06-04 10:11:29,494: [main] DEBUG AbstractLdap.pagedSearch(290) -  - Paginated search with the following parameters:

2018-06-04 10:11:29,494: [main] DEBUG AbstractLdap.pagedSearch(291) -  -   dn = OU=WSU Accounts,dc=tempad,dc=wsu,dc=edu

2018-06-04 10:11:29,494: [main] DEBUG AbstractLdap.pagedSearch(292) -  -   filter = (cn=guenther)

2018-06-04 10:11:29,494: [main] DEBUG AbstractLdap.pagedSearch(293) -  -   filterArgs = []

 

 

Here is the ldaps bind:

 

2018-06-04 10:49:20,719: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(504) -  - LDAP Url: ldaps://somehost.wsu.edu:636/dc=tempad,dc=wsu,dc=edu

2018-06-04 10:49:20,719: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(510) -  - Testing SSL before the LDAP test

2018-06-04 10:49:20,719: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(530) -  -   Making SSL connection to somehost.wsu.edu:636

2018-06-04 10:49:20,886: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(544) -  - Successfully connected

2018-06-04 10:49:20,887: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.buildLdapConnectionPool(89) -  - pspng_activedirectory: Creating LDAP Pool

2018-06-04 10:49:20,940: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.performTestLdapRead(178) -  - Performing test read of directory root

2018-06-04 10:49:21,083: [DefaultQuartzScheduler_Worker-1] INFO  LdapSystem.performTestLdapRead(198) -  - Search success: 

2018-06-04 10:49:21,088: [DefaultQuartzScheduler_Worker-4] DEBUG LdapSystem.buildLdapConnectionPool(154) -  - pspng_activedirectory: Using default onCheckOut ldap-connection validation

2018-06-04 10:49:21,362: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.performTestLdapRead(178) -  - Performing test read of directory root

2018-06-04 10:49:21,368: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(553) -  - Success: Ldap pool built

2018-06-04 10:49:21,381: [DefaultQuartzScheduler_Worker-4] INFO  LdapSystem.test(556) -  - Success: Test ldap read

 

And this is what I have configured:

 

ldap.pspng_activedirectory.url = "ldaps://somehost.wsu.edu:636/dc=tempad,dc=wsu,dc=edu

ldap.pspng_activedirectory.user = cn=grouper.writer,ou=service accounts ,dc=tempad,dc=wsu,dc=edu

ldap.pspng_activedirectory.pass = *******************

ldap.pspng_activedirectory.pagedResultsSize = 1000

ldap.pspng_activedirectory.referral = follow

ldap.pspng_activedirectory.searchResultHandlers=edu.vt.middleware.ldap.handler.FqdnSearchResultHandler,edu.vt.middleware.ldap.handler.EntryDnSearchResultHandler,edu.vt.middleware.ldap.handler.BinarySearchResultHandler,edu.internet2.middleware.grouper.ldap.handler.RangeSearchResultHandler

changeLog.consumer.pspng_activedirectory.provisionerName = pspng_activedirectory

changeLog.consumer.pspng_activedirectory.class = edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim

changeLog.consumer.pspng_activedirectory.type = edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner

changeLog.consumer.pspng_activedirectory.quartzCron = 15 * * * * ?

changeLog.consumer.pspng_activedirectory.ldapPoolName = pspng_activedirectory

changeLog.consumer.pspng_activedirectory.isActiveDirectory = true

changeLog.consumer.pspng_activedirectory.memberAttributeName = member

changeLog.consumer.pspng_activedirectory.memberAttributeValueFormat = ${ldapUser.getDn()}

changeLog.consumer.pspng_activedirectory.groupSearchBaseDn = ou=grouper groups,ou=provisioned groups,ou=enterprise groups,ou=wsu authorization groups,dc=tempad,dc=wsu,dc=edu

changeLog.consumer.pspng_activedirectory.groupSearchAttributes = cn,samAccountName,objectclass

changeLog.consumer.pspng_activedirectory.allGroupsSearchFilter = objectclass=group

changeLog.consumer.pspng_activedirectory.singleGroupSearchFIlter = (&(objectclass=group)(cn=${group.name}))

changeLog.consumer.pspng_activedirectory.groupCreationLdifTemplate = dn: cn=${group.name}||cn: ${group.name}||objectclass: group

 

What do I look at next to figure out my problem with loader trying to fetch info from AD? thanks -- Dean

 

 

Dean Guenther                          
Washington State University    Phone:    509 335-0433
Pullman, WA. 99164-1222        fax:      509 335-0540
Identity and Access Management Manager

 

Attachment: grouper_error.log.tar.gz
Description: grouper_error.log.tar.gz