Grouper Users - Open Discussion List

["Guenther, Dean R." <>]

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={}, utils=edu.internet2.middleware.grouper.pspng.PspJexlUtils@6fee6adc, 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