|
Hello Bert,
any news about this ?
I continue to debug, and you was right grouperIsAuthoritative
setting is not the responsible, i have this problem even if
grouperIsAutoritative is set to false...
It's strange because sometimes deletion work and sometimes not...
the log below suggest that the deleteGroup is ignored :
2018-05-23
16:35:00,065: [DefaultQuartzScheduler_Worker-10] INFO
ProvisioningWorkItem.setStatus(143) - - Work item handled:
ProvisioningWorkItem[successful=true,msg=Ignoring work item
because group is not provisioned,clog=clog #3923078 / ChangeLog
type: group: deleteGroup,group=app:test-pspng723052018]
I think it's the same problem exposed in this
jira.
Thanks a lot,
Yoann.
| Yoann Delattre
|
✆ |
03 20 95 69 10 |
✉ |
|
Équipe SIAD (Systèmes
d'Information et Aide à la Décision)
DSI de
l'académie de Lille (Direction des Systèmes
d'Information)
110 avenue
Gaston Berger - 59000 Lille |
Le 05/02/2018 à 10:33, Yoann Delattre a
écrit :
Hello Bert,
thanks for your answer and your help :)
I set this lines in log4j.properties :
log4j.logger.edu.internet2.middleware.grouper.pspng=DEBUG
log4j.logger.edu.internet2.middleware.grouper.changeLog=DEBUG
and this is what i get in the log :
2018-02-05
10:17:50,033: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangeLogTempToEntity.processMembershipDelete(880) - -
Processing change: ChangeLogEntry: changeLogTypeId:
'82b47b347a834450825cdce3795f280a', contextId:
'112ef6ce7c3447e0a2aa5d3f09ef4b71', createdOnDb:
'1517822220016000', hibernateVersionNumber: '-1', string01:
'db39f38333094a6fafb5f00f7a6c3c1b', string02: 'members',
string03: 'cdupond', string04: 'ldapPerso', string05:
'immediate', string06: 'a8d8b1ce1bca4278a2a18b4f2f3f2d0d',
string07: 'services:test', string08:
'00b264a2fcff48a5a2c53caec921c4c7', string09:
'80cc7f6e67374253ae0a0cde3b99b894', string11: 'cdupond'
2018-02-05 10:17:50,104: [DefaultQuartzScheduler_Worker-1]
DEBUG ChangeLogTempToEntity.processMembershipDelete(880) - -
Processing change: ChangeLogEntry: changeLogTypeId:
'82b47b347a834450825cdce3795f280a', contextId:
'112ef6ce7c3447e0a2aa5d3f09ef4b71', createdOnDb:
'1517822220038000', hibernateVersionNumber: '-1', string01:
'3dbaae0a4efa4ea888e49def1d5ab608', string02: 'members',
string03: 'ydupont2', string04: 'ldapPerso',
string05: 'immediate', string06:
'a8d8b1ce1bca4278a2a18b4f2f3f2d0d', string07: 'services:test',
string08: '14f6604a977f406fb2ffe18faed1374e', string09:
'80cc7f6e67374253ae0a0cde3b99b894', string11: 'ydupont2'
2018-02-05 10:17:50,132: [DefaultQuartzScheduler_Worker-1]
DEBUG ChangeLogTempToEntity.processPrivilegeDelete(982) - -
Processing change: ChangeLogEntry: changeLogTypeId:
'710fdd8d82604e4787af9058465d345c', contextId:
'112ef6ce7c3447e0a2aa5d3f09ef4b71', createdOnDb:
'1517822220125000', hibernateVersionNumber: '-1', string01:
'54821537ab6c4b8fbdc17021c4a56959', string02: 'admin',
string03: 'ydupont2', string04: 'ldapPerso',
string05: 'access', string06: 'group', string07:
'a8d8b1ce1bca4278a2a18b4f2f3f2d0d', string08: 'services:test',
string09: '14f6604a977f406fb2ffe18faed1374e', string10:
'395e9f04269f4e2e978caff68aa41498', string11: 'immediate'
2018-02-05 10:17:50,154: [DefaultQuartzScheduler_Worker-1]
DEBUG ChangeLogTempToEntity.processGroupDelete(320) - -
Processing change: ChangeLogEntry: changeLogTypeId:
'72b2df94eee047a7a6c0f29bf4509543', contextId:
'112ef6ce7c3447e0a2aa5d3f09ef4b71', createdOnDb:
'1517822220271000', hibernateVersionNumber: '-1', string01:
'a8d8b1ce1bca4278a2a18b4f2f3f2d0d', string02: 'services:test',
string03: 'cbfa1ca0e04f4de39687b95d9c7a0556', string04:
'Services:test', string06: '100000022368'
2018-02-05 10:18:00,038: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(199) - -
Processing event number 3922284, membership, deleteMembership
2018-02-05 10:18:00,046: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(199) - -
Processing event number 3922285, membership, deleteMembership
2018-02-05 10:18:00,051: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(199) - -
Processing event number 3922286, privilege, deletePrivilege
2018-02-05 10:18:00,051: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(234) - -
Unsupported event privilege, deletePrivilege, 3922286
2018-02-05 10:18:00,051: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(199) - -
Processing event number 3922287, group, deleteGroup
2018-02-05 10:18:00,051: [DefaultQuartzScheduler_Worker-2]
DEBUG RuleConsumer.processChangeLogEntries(234) - -
Unsupported event group, deleteGroup, 3922287
2018-02-05 10:18:00,070: [DefaultQuartzScheduler_Worker-2]
DEBUG ChangeLogHelper.processRecords(314) - - consumerName:
grouperRules, last sequence processed: 3922283, 0: number of
records found to process: 4, 0: processed to record number:
3922287, totalRecordsProcessed: 4
2018-02-05 10:18:00,125: [DefaultQuartzScheduler_Worker-3]
DEBUG PspChangelogConsumerShim.<init>(42) - -
Constructing PspngChangelogConsumerShim
2018-02-05 10:18:00,135: [DefaultQuartzScheduler_Worker-3]
INFO PspChangelogConsumerShim.processChangeLogEntries(52) -
- pspng_brancheGrouper: +processChangeLogEntries(4)
2018-02-05 10:18:00,136: [DefaultQuartzScheduler_Worker-3]
INFO Provisioner.flushCachesIfNecessary(1434) - -
pspng_brancheGrouper: Keeping caches in tact for provisioning
batch
2018-02-05 10:18:00,136: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.filterWorkItems(428) - - Filtering
provisioning batch of 4 items
2018-02-05 10:18:00,153: [DefaultQuartzScheduler_Worker-3]
INFO ProvisioningWorkItem.setStatus(143) - - Work item
handled: ProvisioningWorkItem[successful=true,msg=Ignoring
work item because group is not provisioned,clog=clog #3922284
/
ChangeLog type: membership:
deleteMembership,group=services:test,subject=cdupond@ldapPerso]
2018-02-05 10:18:00,154: [DefaultQuartzScheduler_Worker-3]
INFO ProvisioningWorkItem.setStatus(143) - - Work item
handled: ProvisioningWorkItem[successful=true,msg=Ignoring
work item because group is not provisioned,clog=clog #3922285
/
ChangeLog type: membership:
deleteMembership,group=services:test,subject=ydupont2@ldapPerso]
2018-02-05 10:18:00,154: [DefaultQuartzScheduler_Worker-3]
DEBUG ProvisioningWorkItem.getGroupName(206) - - Not a
supported change for finding group (ChangeLog type: privilege:
deletePrivilege is not GROUP_ADD, GROUP_DELETE,
MEMBERSHIP_ADD, nor MEMBERSHIP_DELETE): 3922286
2018-02-05 10:18:00,154: [DefaultQuartzScheduler_Worker-3]
INFO ProvisioningWorkItem.setStatus(143) - - Work item
handled: ProvisioningWorkItem[successful=true,msg=Ignoring
work item because group is not provisioned,clog=clog #3922287
/
ChangeLog type: group: deleteGroup,group=services:test]
2018-02-05 10:18:00,155: [DefaultQuartzScheduler_Worker-3]
INFO Provisioner.provisionBatchOfItems(1362) - -
pspng_brancheGrouper: 1 work items need to be processed
further
2018-02-05 10:18:00,155: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.startProvisioningBatch(455) - - Starting
provisioning batch of 1 items
2018-02-05 10:18:00,155: [DefaultQuartzScheduler_Worker-3]
DEBUG ProvisioningWorkItem.getGroupName(206) - - Not a
supported change for finding group (ChangeLog type: privilege:
deletePrivilege is not GROUP_ADD, GROUP_DELETE,
MEMBERSHIP_ADD, nor MEMBERSHIP_DELETE): 3922286
2018-02-05 10:18:00,155: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.prepareGroupCache(692) - - Starting to
cache group information for 0 items
2018-02-05 10:18:00,156: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.prepareUserCache(609) - - Starting to cache
user information for 0 items
2018-02-05 10:18:00,156: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.provisionItem(911) - - Starting
provisioning of item: ProvisioningWorkItem[clog=clog #3922286
/ ChangeLog type: privilege: deletePrivilege]
2018-02-05 10:18:00,157: [DefaultQuartzScheduler_Worker-3]
INFO ProvisioningWorkItem.setStatus(143) - - Work item
handled: ProvisioningWorkItem[successful=true,msg=Nothing to
do (not a supported change),clog=clog #3922286 / ChangeLog
type: privilege: deletePrivilege]
2018-02-05 10:18:00,157: [DefaultQuartzScheduler_Worker-3]
DEBUG LdapProvisioner.makeCoalescedLdapChanges(340) - -
pspng_brancheGrouper: Making coalescedLdapChanges
2018-02-05 10:18:00,157: [DefaultQuartzScheduler_Worker-3]
DEBUG Provisioner.finishProvisioningBatch(485) - - Done with
provisining batch
2018-02-05 10:18:00,157: [DefaultQuartzScheduler_Worker-3]
INFO PspChangelogConsumerShim.processChangeLogEntries(113) -
- Provisioning summary:
2018-02-05 10:18:00,165: [DefaultQuartzScheduler_Worker-3]
DEBUG ChangeLogHelper.processRecords(314) - - consumerName:
pspng_brancheGrouper, last sequence processed: 3922283, 0:
number of records found to process: 4, 0: processed to record
number: 3922287, totalRecordsProcessed: 4
2018-02-05 10:18:01,331:
[pspng_brancheGrouper-FullSync-MessageReaderThread] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(334) -
- pspng_brancheGrouper-FullSync message reader: requesting
messages from queue pspng_full_sync_pspng_brancheGrouper
2018-02-05 10:18:01,332:
[pspng_brancheGrouper-FullSync-MessageReaderThread] INFO
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) -
- pspng_brancheGrouper-FullSync message reader: no messages
received
2018-02-05 10:18:04,023: [DefaultQuartzScheduler_Worker-4]
INFO EventLog.info(156) - -
[bd92bbb9b50445c6b5ce48cb772f6470,'GrouperSystem','application']
session: start (1ms)
2018-02-05 10:18:04,050: [DefaultQuartzScheduler_Worker-4]
DEBUG ChangeLogHelper.processRecords(314) - - consumerName:
syncGroups, last sequence processed: 3922283, 0: number of
records found to process: 4, 0: processed to record number:
3922287, totalRecordsProcessed: 4
Thanks,
Yoann
Le 03/02/2018 à 18:47, Bee-Lindgren,
Bert a écrit :
Hello,
Here is what should
be expected with group deletion:
1) Group deletion
actions should be propagated to the ldap server regardless
of the grouperIsAuthoritative setting. During this process,
the following might be logged
If the query for
point-in-time group information failed when getting ready to
delete the group:
workItem.markAsSkippedAndWarn("Ignoring
group-deletion event because group information was not found
in grouper");
If the group was not found in an ldap search
LOG.warn("Nothing to do: Unable to delete group
{} because the group wasn't found on target system",
grouperGroupInfo);
If the group was found by an ldap search
LOG.info("Deleting group {} by deleting DN {}",
grouperGroupInfo, dn);
2) If the grouperIsAuthoritative setting is true, then
scheduled FullSyncs will include a "Group Cleanup" process:
comparison of all the marked-for-provisioning groups in
grouper with all the groups found by an allGroupsSearchFilter
search on base groupSearchBaseDn. This process logs
some of the following:
FYI, if Grouper is not authoritative, the FullSync schedule
should log:
LOG.warn("{}: Ignoring group-cleanup because
grouper is not authoritative", getName());
The start of the Group Cleanup:
LOG.info("{}: Starting Group Cleanup ({})",
getName(), queueItem.reason);
Progress is logged at debug level:
LOG.debug("Doing ldap search: <filter> /
<base> / <attributes>",
After the group-list comparisons are done:
LOG.info("{}: There are {} groups that we should
delete", getName(), groupsToDelete.size());
(This will log "There are 0 groups that we should
delete" if everything is in sync)
For each extra group found in LDAP (that is not in Grouper
or is not labeled for provisioning):
LOG.info("{}: Deleting LDAP object: {}",
ldapSystemName, dnToDelete);
The end of the Group Cleanup:
LOG.info("{}: Group-cleanup done. Stats: {}",
getName(), queueItem.stats);
It seems clear that your experiences don't match these
expectations, particularly in that you're seeing
changelog-event-triggered group-deletion depend on the
grouperIsAuthoritative setting. As listed above, there are
several INFO-level messages logged during this processing. I
don't see problems with your configuration.
Can you run with such logging enabled and forward it to me?
Sincerely,
Bert Bee-Lindgren
From:
on behalf of Yoann Delattre
Sent: Thursday, February 1, 2018 2:45 AM
To:
Subject: Re: [grouper-users] [PSPNG] Not deleting
groups in LDAP
Hello !
anyone ?
Thanks !
Yoann
Le 18/12/2017 à 09:22,
Yoann Delattre a écrit :
Hello everyone,
for summarise :
When grouperIsAuthoritative is set to true, a
group deleted in Grouper are not deleted in LDAP.
No problem when i create groups or delete members :
all this changes are provisioned correctly in the
LDAP.
Has anyone ran into this issue?
Thanks,
Yoann.
Le 11/12/2017 à 16:02,
Yoann Delattre a écrit :
grouperIsAuthoritative was set to true.
So i tried set it to false, and now it
works...Strange :-/
maybe something wrong with my conf ?
changeLog.consumer.pspng_brancheGrouper.class =
edu.internet2.middleware.grouper.pspng.PspChangelogConsumerShim
changeLog.consumer.pspng_brancheGrouper.type =
edu.internet2.middleware.grouper.pspng.LdapGroupProvisioner
changeLog.consumer.pspng_brancheGrouper.quartzCron =
0 * * * * ?
changeLog.consumer.pspng_brancheGrouper.ldapPoolName
= aclille
changeLog.consumer.pspng_brancheGrouper.memberAttributeName =
uniqueMember
changeLog.consumer.pspng_brancheGrouper.memberAttributeValueFormat =
${ldapUser.getDn()}
changeLog.consumer.pspng_brancheGrouper.groupSearchBaseDn =
ou=Grouper,ou=xxxxx,o=yyyy,c=zz
changeLog.consumer.pspng_brancheGrouper.allGroupsSearchFilter =
objectclass=groupOfUniqueNames
changeLog.consumer.pspng_brancheGrouper.singleGroupSearchFilter =
(&(objectclass=groupOfUniqueNames)(cn=${group.name}))
changeLog.consumer.pspng_brancheGrouper.groupSearchAttributes =
cn,objectclass
changeLog.consumer.pspng_brancheGrouper.groupCreationLdifTemplate = dn:
cn=${group.name}||cn: ${group.name}||objectclass:
groupOfUniqueNames||objectclass: educationnationale
changeLog.consumer.pspng_brancheGrouper.userSearchBaseDn =
ou=people,ou=xxxxx,o=yyyy,c=zz
changeLog.consumer.pspng_brancheGrouper.userSearchFilter =
uid=${subject.id}
changeLog.consumer.pspng_brancheGrouper.grouperIsAuthoritative = false
Thanks for your help !
Yoann
Le 11/12/2017 à 15:18,
Jeffrey Williams a écrit :
Hi Yoann,
My first thought was whether you had grouperIsAuthoritative set?
Should
groups in the
groupSearchBaseDn/allGroupSearchFilter be
removed if they no longer exist in Grouper?
By default, it is set to FALSE, which sounds
like the behavior you're experiencing.
|
