|
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.
|
