grouper-users - Re: [grouper-users] AD Provisioning not working on delete

Subject: Grouper Users - Open Discussion List

List archive

Re: [grouper-users] AD Provisioning not working on delete

From: Oliver Trieu <>
To: Jeffrey Williams <>
Cc: "Hyzer, Chris" <>, Grouper-Users <>
Subject: Re: [grouper-users] AD Provisioning not working on delete
Date: Wed, 23 Oct 2019 11:40:32 +0200
Organization: University of Vienna

Hi Jeffrey,

thank you for your time, of course i can.

I created a new Group using the grouper-gui (GROUP2).

I waited until it was provisioned to AD and then deleted it in grouper.

The attached log file shows the creation and deletion of the group (not_working.txt).

I should add that oddly enough on my first try it actually worked!

It seems to be kind of random as i did the exact same thing (created group, waited for provisioning, then deleted).

I also attached this logfile (worked_strange.txt).

I did not change any settings between these tries...

Kind Regards

Oliver

On 10/22/19 11:41 PM, Jeffrey Williams wrote:

Hi Oliver,

Can you turn up the logging on your provisioner to DEBUG and delete a group?

On Tue, Oct 22, 2019, 1:21 AM Oliver Trieu <> wrote:

Dear Chris,

thank you for your fast response!

Here is the information you asked for:

grouperPatchStatus read from: /opt/grouper.apiBinary-2.4.0/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, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74

pspng patches installed: 0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11

Kind Regards

Oliver

Am 21.10.2019 um 17:28 schrieb Hyzer, Chris:

Can you please confirm which patches you have installed?

-----Original Message-----
From:   On Behalf Of Oliver Trieu
Sent: Thursday, October 17, 2019 4:13 AM
To: 
Subject: [grouper-users] AD Provisioning not working on delete

Hi fellow Grouper Users,

i have the grouper 2.4.0 up and running provisioning into our Microsoft 
AD server.

The provisioning of new Groups works just fine, but when i delete the 
new group it does NOT get deleted in the AD.

Somehow grouper thinks it did not provision the group and thus does not 
delete it.

What could be the cause of this issue?

Here is the log-snippet to show the problem:

2019-10-16 11:31:00 INFO  Starting provisioning batch of 1 items
2019-10-16 11:31:00 INFO  Information cached before 
2019-10-16T11:30:04.881+02:00 will be ignored
2019-10-16 11:31:00 INFO  LDAP search returned 0 entries
2019-10-16 11:31:00 INFO  Creating LDAP group for GrouperGroup: 
...:NEW_GROUP/#12110(Existing)
2019-10-16 11:31:00 INFO  pspng_activedirectory: Creating LDAP object: 
cn=NEW_GROUP,ou=...
2019-10-16 11:31:00 INFO  pspng_activedirectory: Checking for (and 
creating) missing OUs in DN: cn=NEW_GROUP,ou=... (wholeDnIsOu=false)
2019-10-16 11:31:00 INFO  active_directory: Creating LDAP object Entry 
Summary: dn=cn=NEW_GROUP,ou=...|1 cn values|2 objectclass values|
2019-10-16 11:31:00 INFO  LDAP search returned 1 entries
2019-10-16 11:31:00 INFO  Work item handled: 
ProvisioningWorkItem[done=true,successful=true,msg=Group 
...l:NEW_GROUP/#12110(Existing) already exists,clog=clog #2071223 / 
ChangeLog type: group: addGroup,group=..:NEW_GROUP]

2019-10-16 11:31:00 INFO  Provisioning batch summary: 3 successes/0 
failures. Duration=00.788s

Now it is provisioned but when i delete the same object:

2019-10-16 11:40:00 INFO  pspng_activedirectory: +processChangeLogEntries(1)
2019-10-16 11:40:00 WARN  Unable to refresh object from database, 
probably because it has been deleted: 
Group[name=...:NEW_GROUP,uuid=3221ae657f2b4666b008e40086d8350d]
2019-10-16 11:40:00 WARN  Work item handled: 
ProvisioningWorkItem[done=true,successful=true,msg=Ignoring work item 
because (deleted) group was not provisioned before it was 
deleted,clog=clog #2071225 / ChangeLog type: group: 
deleteGroup,group=...:NEW_GROUP]
2019-10-16 11:40:00 INFO  pspng_activedirectory: 0 work items need to be 
processed further
2019-10-16 11:40:00 INFO  Starting provisioning batch of 0 items
2019-10-16 11:40:00 INFO  Information cached before null will be ignored
2019-10-16 11:40:00 INFO  Provisioning batch summary: 1 successes/0 
failures. Duration=00.005s

Grouper decides to not delete it!

I have a similar issue with Folders where grouper will only provision 
the folder if i create a group in that folder and deleting the folder 
will not provision the delete to the AD.

A full sync however will bring the groups in sync but not the folders ...

Kind Regards

Oliver

PS: here is my grouper-loader config for the AD Provisioner:

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 = 0 * * * * ?
changeLog.consumer.pspng_activedirectory.ldapPoolName = active_directory
changeLog.consumer.pspng_activedirectory.isActiveDirectory = true
changeLog.consumer.pspng_activedirectory.grouperIsAuthoritative = true
changeLog.consumer.pspng_activedirectory.memberAttributeName = member
changeLog.consumer.pspng_activedirectory.memberAttributeValueFormat = 
${ldapUser.getDn()}
changeLog.consumer.pspng_activedirectory.groupSearchBaseDn = ou=...
changeLog.consumer.pspng_activedirectory.allGroupsSearchFilter = 
objectclass=group
changeLog.consumer.pspng_activedirectory.singleGroupSearchFilter = 
(&(objectclass=group)(cn=${grouperUtil.extensionFromName(group.name)}))
changeLog.consumer.pspng_activedirectory.groupCreationLdifTemplate = dn: 
${utils.bushyDn(group.name, "cn", "ou")}||cn: 
${grouperUtil.extensionFromName(group.name)}||objectclass: 
group||objectclass: top
changeLog.consumer.pspng_activedirectory.userSearchBaseDn = ou=...
changeLog.consumer.pspng_activedirectory.userSearchFilter = 
samAccountName=${subject.id}

-- 
Oliver Trieu
Managed Services 
Server and Data Management

Universität Wien
Zentraler Informatikdienst
Universitätsstrasse 7, 1010 Wien

T +43-1-4277-14161
M: +43-664-60277-14161

zid.univie.ac.at

2019-10-23 11:11:50,025: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogTempToEntity.processGroupAdd(338) - - Processing change:
ChangeLogEntry: changeLogTypeId: '45b92a3c36664c1bbe0651f62e4db501',
contextId: 'efe2857c57bd4e42b32dc8d7b311cb5a', createdOnDb:
'1571821865083000', hibernateVersionNumber: '-1', string01:
'9cff9428e08946bc823b40c971ea2884', string02: '...:GROUP2', string03:
'078b470b69b047e39d2cbe01c5fa912d', string04: '...:GROUP2', string06: '12124'
2019-10-23 11:11:50,534: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogTempToEntity.processMemberAdd(807) - - Processing change:
ChangeLogEntry: changeLogTypeId: '357112a3333c4355a15b940b77e00268',
contextId: 'efe2857c57bd4e42b32dc8d7b311cb5a', createdOnDb:
'1571821865435000', hibernateVersionNumber: '-1', string01:
'4e8c0b2ec5eb4085ae50c43f6a61e40f', string02:
'9cff9428e08946bc823b40c971ea2884', string03: 'g:gsa', string04: 'group',
string05: '...:GROUP2'
2019-10-23 11:12:00,026: [DefaultQuartzScheduler_Worker-9] DEBUG
RuleConsumer.processChangeLogEntries(199) - - Processing event number
2071252, group, addGroup
2019-10-23 11:12:00,026: [DefaultQuartzScheduler_Worker-9] DEBUG
RuleConsumer.processChangeLogEntries(234) - - Unsupported event group,
addGroup, 2071252
2019-10-23 11:12:00,027: [DefaultQuartzScheduler_Worker-9] DEBUG
RuleConsumer.processChangeLogEntries(199) - - Processing event number
2071253, member, addMember
2019-10-23 11:12:00,027: [DefaultQuartzScheduler_Worker-9] DEBUG
RuleConsumer.processChangeLogEntries(234) - - Unsupported event member,
addMember, 2071253
2019-10-23 11:12:00,029: [DefaultQuartzScheduler_Worker-9] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071251, 0: number of records found to process: 2, 0:
processed to record number: 2071253, totalRecordsProcessed: 2
2019-10-23 11:12:00,050: [DefaultQuartzScheduler_Worker-1] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:12:00,052: [DefaultQuartzScheduler_Worker-1] INFO
PspChangelogConsumerShim.processChangeLogEntries(55) - -
pspng_activedirectory: +processChangeLogEntries(2)
2019-10-23 11:12:00,052: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupNameFieldLabels.get(2071252/ChangeLog type: group: addGroup)=name
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.uncacheGroup(1165) - - Flushing group from target-system cache:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.uncacheGroup(1168) - - Flushing group from pspng group-info
cache: ...:GROUP2
2019-10-23 11:12:00,054: [DefaultQuartzScheduler_Worker-1] DEBUG
PspUtils.hibernateRefresh(318) - - Rereading group information from
database: class
edu.internet2.middleware.grouper.Group/Group[name=...:GROUP2,uuid=9cff9428e08946bc823b40c971ea2884]
2019-10-23 11:12:00,055: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.filterWorkItems(467) - - Filtering provisioning batch of 2 items
2019-10-23 11:12:00,055: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,055: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,056: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,056: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,086: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated GroupSelection Jexl
expression: 'true'
2019-10-23 11:12:00,086: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire GroupSelection
Jexl expression: 'true'
2019-10-23 11:12:00,086: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.shouldGroupBeProvisioned(1820) - - pspng_activedirectory: Group
...:GROUP2/#12124(Existing) matches group-selection filter.
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,087: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupNameFieldLabels.get(2071253/ChangeLog type: member: addMember)=null
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(197) - - ChangelogConfig:
GroupNameFieldLabels.get(2071253/ChangeLog type: member: addMember)=null
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(197) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071253/ChangeLog type: member: addMember)=subjectId
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(197) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071253/ChangeLog type: member:
addMember)=subjectSourceId
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(197) - - Group name not found in work
item: ProvisioningWorkItem[done=false,clog=clog #2071253 / ChangeLog type:
member: addMember,subject=9cff9428e08946bc823b40c971ea2884@g:gsa]
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071253/ChangeLog type: member: addMember)=subjectId
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071253/ChangeLog type: member:
addMember)=subjectSourceId
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071253/ChangeLog type: member: addMember)=subjectId
2019-10-23 11:12:00,088: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071253/ChangeLog type: member:
addMember)=subjectSourceId
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071253/ChangeLog type: member: addMember)=subjectId
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071253/ChangeLog type: member:
addMember)=subjectSourceId
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(141) - - ChangelogConfig:
GroupNameFieldLabels.get(2071253/ChangeLog type: member: addMember)=null
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(141) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071253/ChangeLog type: member: addMember)=subjectId
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(141) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071253/ChangeLog type: member:
addMember)=subjectSourceId
2019-10-23 11:12:00,094: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(141) - - Work item handled:
ProvisioningWorkItem[done=true,successful=true,msg=Ignoring event about a
g:gsa subject,clog=clog #2071253 / ChangeLog type: member:
addMember,subject=9cff9428e08946bc823b40c971ea2884@g:gsa]
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] INFO
Provisioner.provisionBatchOfItems(1871) - - pspng_activedirectory: 1 work
items need to be processed further
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisionerCoordinator$ProvisioningStatus.lockForIncrementalProvisioningWhenNoFullSyncIsUnderway(139)
- - pspng_activedirectory: Locking group before incremental sync:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,095: [DefaultQuartzScheduler_Worker-1] INFO
Provisioner.startProvisioningBatch(603) - - Starting provisioning batch of 1
items
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper groups is sufficiently sized (0% full) (property
grouperGroupCacheSize=100000)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned groups is sufficiently sized (0% full) (property
targetSystemGroupCacheSize=10000)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper subjects is sufficiently sized (0% full) (property
grouperSubjectCacheSize=200000)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned subjects is sufficiently sized (0% full) (property
targetSystemUserCacheSize=100000)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.startProvisioningBatch(609) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.startProvisioningBatch(609) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.startProvisioningBatch(609) - - -->Work item:
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2]
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] INFO
Provisioner.startProvisioningBatch(627) - - Information cached before
2019-10-23T11:11:05.083+02:00 will be ignored
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,096: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.prepareGroupCache(999) - - Starting to cache group information
for 1 items
2019-10-23 11:12:00,097: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.getLdapAttributesToFetch(572) - - Fetching without
membership attribut
2019-10-23 11:12:00,109: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated
SingleGroupSearchFilter Jexl expression: 'GROUP2'
2019-10-23 11:12:00,109: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire
SingleGroupSearchFilter Jexl expression: '(&(objectclass=group)(cn=GROUP2))'
2019-10-23 11:12:00,109: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(531) - - pspng_activedirectory:
Searching for group ...:GROUP2/#12124(Existing) with::
[org.ldaptive.SearchFilter@1514308188::filter=(&(objectclass=group)(cn=GROUP2)),
parameters={}]
2019-10-23 11:12:00,109: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(796) - - Running ldap search:
<ou=group,dc=s,dc=univie,dc=ac,dc=at>/SUBTREE:
(&(objectclass=group)(cn=GROUP2)) << {}
2019-10-23 11:12:00,109: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(730) - - Doing ldap search:
[org.ldaptive.SearchFilter@1514308188::filter=(&(objectclass=group)(cn=GROUP2)),
parameters={}] / ou=group,dc=s,dc=univie,dc=ac,dc=at / [cn, gidNumber,
samAccountName, objectclass]
2019-10-23 11:12:00,335: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(740) - - Using attribute-value paging
2019-10-23 11:12:00,335: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(751) - - Using ldap search-result paging
2019-10-23 11:12:00,337: [DefaultQuartzScheduler_Worker-1] INFO
LdapSystem.performLdapSearchRequest(819) - - LDAP search returned 0 entries
2019-10-23 11:12:00,337: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(552) - - pspng_activedirectory:
Group search did not return any results
2019-10-23 11:12:00,354: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated GroupSelection Jexl
expression: 'true'
2019-10-23 11:12:00,354: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire GroupSelection
Jexl expression: 'true'
2019-10-23 11:12:00,354: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.shouldGroupBeProvisioned(1820) - - pspng_activedirectory: Group
...:GROUP2/#12124(Existing) matches group-selection filter.
2019-10-23 11:12:00,354: [DefaultQuartzScheduler_Worker-1] INFO
LdapGroupProvisioner.createGroup(339) - - Creating LDAP group for
GrouperGroup: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,369: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated GroupTemplate Jexl
expression: 'cn=GROUP2,ou=XXX,ou=YYY'
2019-10-23 11:12:00,369: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated GroupTemplate Jexl
expression: 'GROUP2'
2019-10-23 11:12:00,369: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire GroupTemplate
Jexl expression: 'dn: cn=GROUP2,ou=XXX,ou=YYY
cn: GROUP2
objectclass: group
objectclass: top'
2019-10-23 11:12:00,370: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.createGroup(367) - - pspng_activedirectory: LDIF for
new group (with partial DN): dn: cn=GROUP2,ou=XXX,ou=YYY||cn:
GROUP2||objectclass: group||objectclass: top
2019-10-23 11:12:00,370: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.createGroup(378) - - pspng_activedirectory: Adding
group:
[dn=cn=GROUP2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at[[cn[GROUP2]],
[objectclass[top, group]]]]
2019-10-23 11:12:00,371: [DefaultQuartzScheduler_Worker-1] INFO
LdapProvisioner.performLdapAdd(882) - - pspng_activedirectory: Creating LDAP
object: cn=GROUP2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at
2019-10-23 11:12:00,371: [DefaultQuartzScheduler_Worker-1] INFO
LdapProvisioner.ensureLdapOusExist(770) - - pspng_activedirectory: Checking
for (and creating) missing OUs in DN:
cn=GROUP2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at
(wholeDnIsOu=false)
2019-10-23 11:12:00,371: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapProvisioner.ensureLdapOusExist(807) - - pspng_activedirectory: OU is
known to exist: ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at
2019-10-23 11:12:00,371: [DefaultQuartzScheduler_Worker-1] INFO
LdapSystem.log(196) - - active_directory: Creating LDAP object Entry
Summary: dn=cn=GROUP2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at|1 cn
values|2 objectclass values|
2019-10-23 11:12:00,371: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.log(199) - - active_directory: Creating LDAP object Entry
Details:
[dn=cn=GROUP2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at[[cn[GROUP2]],
[objectclass[top, group]]]]
2019-10-23 11:12:00,616: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.createGroup(383) - - Reading group that was just added
to ldap server: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,616: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.getLdapAttributesToFetch(572) - - Fetching without
membership attribute
2019-10-23 11:12:00,631: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated
SingleGroupSearchFilter Jexl expression: 'GROUP2'
2019-10-23 11:12:00,631: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire
SingleGroupSearchFilter Jexl expression: '(&(objectclass=group)(cn=GROUP2))'
2019-10-23 11:12:00,631: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(531) - - pspng_activedirectory:
Searching for group ...:GROUP2/#12124(Existing) with::
[org.ldaptive.SearchFilter@1514308188::filter=(&(objectclass=group)(cn=GROUP2)),
parameters={}]
2019-10-23 11:12:00,631: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(796) - - Running ldap search:
<ou=group,dc=s,dc=univie,dc=ac,dc=at>/SUBTREE:
(&(objectclass=group)(cn=GROUP2)) << {}
2019-10-23 11:12:00,631: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(730) - - Doing ldap search:
[org.ldaptive.SearchFilter@1514308188::filter=(&(objectclass=group)(cn=GROUP2)),
parameters={}] / ou=group,dc=s,dc=univie,dc=ac,dc=at / [cn, gidNumber,
samAccountName, objectclass]
2019-10-23 11:12:00,632: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(740) - - Using attribute-value paging
2019-10-23 11:12:00,632: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem.performLdapSearchRequest(751) - - Using ldap search-result paging
2019-10-23 11:12:00,634: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapSystem$1.handle(807) - - Ldap result:
CN=GROUP2,ou=XXX,ou=YYY,OU=group,DC=s,DC=univie,DC=ac,DC=at
2019-10-23 11:12:00,635: [DefaultQuartzScheduler_Worker-1] INFO
LdapSystem.performLdapSearchRequest(819) - - LDAP search returned 1 entries
2019-10-23 11:12:00,635: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(542) - - pspng_activedirectory:
Group search returned
cn=group2,ou=XXX,ou=YYY,ou=group,dc=s,dc=univie,dc=ac,dc=at
2019-10-23 11:12:00,636: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.cacheGroup(1125) - - Adding target-system group to cache:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,636: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.prepareUserCache(856) - - Starting to cache user information for
0 items
2019-10-23 11:12:00,636: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.provisionItem(1245) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.provisionItem(1245) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.provisionItem(1245) - - Starting provisioning of item:
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2]
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,637: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071252 / ChangeLog type: group:
addGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,650: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated GroupSelection Jexl
expression: 'true'
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire GroupSelection
Jexl expression: 'true'
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.shouldGroupBeProvisioned(1820) - - pspng_activedirectory: Group
...:GROUP2/#12124(Existing) matches group-selection filter.
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(132) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.setStatus(132) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] INFO
ProvisioningWorkItem.setStatus(132) - - Work item handled:
ProvisioningWorkItem[done=true,successful=true,msg=Group
...:GROUP2/#12124(Existing) already exists,clog=clog #2071252 / ChangeLog
type: group: addGroup,group=...:GROUP2]
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
LdapProvisioner.makeCoalescedLdapChanges(479) - - pspng_activedirectory:
Making coalescedLdapChanges
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.finishProvisioningBatch(700) - - Done with provisining batch
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,651: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=true,successful=true,msg=Group
...:GROUP2/#12124(Existing) already exists,clog=clog #2071252 / ChangeLog
type: group: addGroup,group=...:GROUP2] is related to Group:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisionerCoordinator$ProvisioningStatus.unlockAfterIncrementalProvisioning(160)
- - pspng_activedirectory: Unlocking group after incremental sync:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071252/ChangeLog type: group: addGroup)=null
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=true,successful=true,msg=Group
...:GROUP2/#12124(Existing) already exists,clog=clog #2071252 / ChangeLog
type: group: addGroup,group=...:GROUP2] is related to Group:
...:GROUP2/#12124(Existing)
2019-10-23 11:12:00,652: [DefaultQuartzScheduler_Worker-1] INFO
PspChangelogConsumerShim.processChangeLogEntries(116) - - Provisioning batch
summary: 2 successes/0 failures. Duration=00.600s
2019-10-23 11:12:00,655: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071251, 0: number of records found to process: 2,
0: processed to record number: 2071253, totalRecordsProcessed: 2
2019-10-23 11:12:04,015: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071251, 0: number of records found to process: 2, 0:
processed to record number: 2071253, totalRecordsProcessed: 2
2019-10-23 11:12:14,951: [FullSyncer(pspng_activedirectory)-Thread] DEBUG
FullSyncProvisioner.getNextFullSyncRequest(504) - -
FullSyncer(pspng_activedirectory): No full sync requests found
2019-10-23 11:13:00,019: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:13:00,042: [DefaultQuartzScheduler_Worker-10] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:13:00,045: [DefaultQuartzScheduler_Worker-10] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:13:04,027: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:13:21,020:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-retry] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_retry
2019-10-23 11:13:21,020:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-retry] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/retry message reader: no messages received
2019-10-23 11:13:22,806:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-asap] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_asap
2019-10-23 11:13:22,806:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-asap] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/asap message reader: no messages received
2019-10-23 11:13:24,238:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-background] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_background
2019-10-23 11:13:24,238:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-background] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/background message reader: no messages
received
2019-10-23 11:13:24,604:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-changelog] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_changelog
2019-10-23 11:13:24,605:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-changelog] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/changelog message reader: no messages
received
2019-10-23 11:14:00,016: [DefaultQuartzScheduler_Worker-7] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:14:00,032: [DefaultQuartzScheduler_Worker-8] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:14:00,034: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:14:04,024: [DefaultQuartzScheduler_Worker-9] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:15:00,014: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:15:00,024: [DefaultQuartzScheduler_Worker-3] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:15:00,026: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:15:04,031: [DefaultQuartzScheduler_Worker-10] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:16:00,019: [DefaultQuartzScheduler_Worker-5] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:16:00,033: [DefaultQuartzScheduler_Worker-7] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:16:00,037: [DefaultQuartzScheduler_Worker-7] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:16:04,016: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:17:00,025: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:17:00,037: [DefaultQuartzScheduler_Worker-2] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:17:00,041: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:17:04,013: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:17:14,951: [FullSyncer(pspng_activedirectory)-Thread] DEBUG
FullSyncProvisioner.getNextFullSyncRequest(504) - -
FullSyncer(pspng_activedirectory): No full sync requests found
2019-10-23 11:18:00,014: [DefaultQuartzScheduler_Worker-10] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:18:00,027: [DefaultQuartzScheduler_Worker-6] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:18:00,029: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:18:04,017: [DefaultQuartzScheduler_Worker-5] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:18:28,681:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-asap] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_asap
2019-10-23 11:18:28,682:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-asap] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/asap message reader: no messages received
2019-10-23 11:18:29,849:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-background] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_background
2019-10-23 11:18:29,849:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-background] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/background message reader: no messages
received
2019-10-23 11:18:29,966:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-retry] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_retry
2019-10-23 11:18:29,966:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-retry] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/retry message reader: no messages received
2019-10-23 11:18:30,394:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-changelog] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(335) - -
FullSyncer(pspng_activedirectory) message reader: requesting messages from
queue pspng_full_sync_pspng_activedirectory_changelog
2019-10-23 11:18:30,395:
[FullSyncer(pspng_activedirectory)-MessageReaderThread-changelog] DEBUG
FullSyncProvisioner.thread_fullSyncMessageQueueReader(348) - -
FullSyncer(pspng_activedirectory)/changelog message reader: no messages
received
2019-10-23 11:19:00,015: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:19:00,030: [DefaultQuartzScheduler_Worker-9] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:19:00,032: [DefaultQuartzScheduler_Worker-9] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:19:04,016: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:19:50,019: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogTempToEntity.processGroupDelete(415) - - Processing change:
ChangeLogEntry: changeLogTypeId: '83168f4fd8f84e4dbc4a8850ebbf09c8',
contextId: '11d2333be2134066b88f2e7e698d1edc', createdOnDb:
'1571822346572000', hibernateVersionNumber: '-1', string01:
'9cff9428e08946bc823b40c971ea2884', string02: '...:GROUP2', string03:
'078b470b69b047e39d2cbe01c5fa912d', string04: '...:GROUP2', string06: '12124'
2019-10-23 11:20:00,015: [DefaultQuartzScheduler_Worker-3] DEBUG
RuleConsumer.processChangeLogEntries(199) - - Processing event number
2071254, group, deleteGroup
2019-10-23 11:20:00,016: [DefaultQuartzScheduler_Worker-3] DEBUG
RuleConsumer.processChangeLogEntries(234) - - Unsupported event group,
deleteGroup, 2071254
2019-10-23 11:20:00,018: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071253, 0: number of records found to process: 1, 0:
processed to record number: 2071254, totalRecordsProcessed: 1
2019-10-23 11:20:00,024: [DefaultQuartzScheduler_Worker-4] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:20:00,026: [DefaultQuartzScheduler_Worker-4] INFO
PspChangelogConsumerShim.processChangeLogEntries(55) - -
pspng_activedirectory: +processChangeLogEntries(1)
2019-10-23 11:20:00,026: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupNameFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=name
2019-10-23 11:20:00,026: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group ...:GROUP2/#12124(Existing)
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071254 / ChangeLog type: group:
deleteGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(Existing)
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.uncacheGroup(1165) - - Flushing group from target-system cache:
...:GROUP2/#12124(Existing)
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.uncacheGroup(1168) - - Flushing group from pspng group-info
cache: ...:GROUP2
2019-10-23 11:20:00,027: [DefaultQuartzScheduler_Worker-4] DEBUG
PspUtils.hibernateRefresh(318) - - Rereading group information from
database: class
edu.internet2.middleware.grouper.Group/Group[name=...:GROUP2,uuid=9cff9428e08946bc823b40c971ea2884]
2019-10-23 11:20:00,028: [DefaultQuartzScheduler_Worker-4] WARN
PspUtils.hibernateRefresh(332) - - Unable to refresh object from database,
probably because it has been deleted:
Group[name=...:GROUP2,uuid=9cff9428e08946bc823b40c971ea2884]
2019-10-23 11:20:00,028: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.filterWorkItems(467) - - Filtering provisioning batch of 1 items
2019-10-23 11:20:00,031: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 11:20:00,031: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
...:GROUP2/#12124(PIT)
2019-10-23 11:20:00,031: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,031: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,031: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071254 / ChangeLog type: group:
deleteGroup,group=...:GROUP2] is related to Group: ...:GROUP2/#12124(PIT)
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.setStatus(135) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
ProvisioningWorkItem.setStatus(135) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071254/ChangeLog type: group: deleteGroup)=null
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] WARN
ProvisioningWorkItem.setStatus(135) - - Work item handled:
ProvisioningWorkItem[done=true,successful=true,msg=Ignoring work item because
(deleted) group was not provisioned before it was deleted,clog=clog #2071254
/ ChangeLog type: group: deleteGroup,group=...:GROUP2]
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] INFO
Provisioner.provisionBatchOfItems(1871) - - pspng_activedirectory: 0 work
items need to be processed further
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] INFO
Provisioner.startProvisioningBatch(603) - - Starting provisioning batch of 0
items
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper groups is sufficiently sized (0% full) (property
grouperGroupCacheSize=100000)
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned groups is sufficiently sized (0% full) (property
targetSystemGroupCacheSize=10000)
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper subjects is sufficiently sized (0% full) (property
grouperSubjectCacheSize=200000)
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned subjects is sufficiently sized (0% full) (property
targetSystemUserCacheSize=100000)
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] INFO
Provisioner.startProvisioningBatch(627) - - Information cached before null
will be ignored
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.prepareGroupCache(999) - - Starting to cache group information
for 0 items
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.prepareUserCache(856) - - Starting to cache user information for
0 items
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
LdapProvisioner.makeCoalescedLdapChanges(479) - - pspng_activedirectory:
Making coalescedLdapChanges
2019-10-23 11:20:00,032: [DefaultQuartzScheduler_Worker-4] DEBUG
Provisioner.finishProvisioningBatch(700) - - Done with provisining batch
2019-10-23 11:20:00,033: [DefaultQuartzScheduler_Worker-4] INFO
PspChangelogConsumerShim.processChangeLogEntries(116) - - Provisioning batch
summary: 1 successes/0 failures. Duration=00.006s
2019-10-23 11:20:00,035: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071253, 0: number of records found to process: 1,
0: processed to record number: 2071254, totalRecordsProcessed: 1
2019-10-23 11:20:04,019: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071253, 0: number of records found to process: 1, 0:
processed to record number: 2071254, totalRecordsProcessed: 1
2019-10-23 11:21:00,017: [DefaultQuartzScheduler_Worker-7] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071254, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 11:21:00,028: [DefaultQuartzScheduler_Worker-8] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 11:21:00,031: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071254, 0: number of records found to process: 0,
totalRecordsProcessed: 0

2019-10-23 09:51:50,017: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogTempToEntity.processGroupDelete(415) - - Processing change:
ChangeLogEntry: changeLogTypeId: '83168f4fd8f84e4dbc4a8850ebbf09c8',
contextId: '6ee3096fc6754e478c6f1083f5aca9e6', createdOnDb:
'1571817073746000', hibernateVersionNumber: '-1', string01:
'ad467552f9a540c793195fd86303fbce', string02: 'XXX:YYY:NEW_GROUP_WITH_DEBUG',
string03: '078b470b69b047e39d2cbe01c5fa912d', string04:
'XXX:YYY:NEW_GROUP_WITH_DEBUG', string06: '12111'
2019-10-23 09:52:00,017: [DefaultQuartzScheduler_Worker-4] DEBUG
RuleConsumer.processChangeLogEntries(199) - - Processing event number
2071243, group, deleteGroup
2019-10-23 09:52:00,017: [DefaultQuartzScheduler_Worker-4] DEBUG
RuleConsumer.processChangeLogEntries(234) - - Unsupported event group,
deleteGroup, 2071243
2019-10-23 09:52:00,019: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071242, 0: number of records found to process: 1, 0:
processed to record number: 2071243, totalRecordsProcessed: 1
2019-10-23 09:52:00,028: [DefaultQuartzScheduler_Worker-6] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 09:52:00,032: [DefaultQuartzScheduler_Worker-6] INFO
PspChangelogConsumerShim.processChangeLogEntries(55) - -
pspng_activedirectory: +processChangeLogEntries(1)
2019-10-23 09:52:00,032: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupNameFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=name
2019-10-23 09:52:00,033: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1679) - - pspng_activedirectory: Found existing
group XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(Existing)
2019-10-23 09:52:00,033: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,033: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,033: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(Existing)
2019-10-23 09:52:00,033: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.uncacheGroup(1165) - - Flushing group from target-system cache:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(Existing)
2019-10-23 09:52:00,034: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.uncacheGroup(1168) - - Flushing group from pspng group-info
cache: XXX:YYY:NEW_GROUP_WITH_DEBUG
2019-10-23 09:52:00,034: [DefaultQuartzScheduler_Worker-6] DEBUG
PspUtils.hibernateRefresh(318) - - Rereading group information from
database: class
edu.internet2.middleware.grouper.Group/Group[name=XXX:YYY:NEW_GROUP_WITH_DEBUG,uuid=ad467552f9a540c793195fd86303fbce]
2019-10-23 09:52:00,035: [DefaultQuartzScheduler_Worker-6] WARN
PspUtils.hibernateRefresh(332) - - Unable to refresh object from database,
probably because it has been deleted:
Group[name=XXX:YYY:NEW_GROUP_WITH_DEBUG,uuid=ad467552f9a540c793195fd86303fbce]
2019-10-23 09:52:00,036: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.filterWorkItems(467) - - Filtering provisioning batch of 1 items
2019-10-23 09:52:00,042: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,042: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,042: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,042: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,043: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,043: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,043: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,043: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,044: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,044: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,044: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,044: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,044: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,046: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,046: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,046: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.shouldWorkItemBeProcessed(534) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.shouldWorkItemBeProcessed(534) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.shouldWorkItemBeProcessed(534) - - pspng_activedirectory: Group
has been deleted within grouper, so we're processing group-deletion event:
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG]
2019-10-23 09:52:00,047: [DefaultQuartzScheduler_Worker-6] INFO
Provisioner.provisionBatchOfItems(1871) - - pspng_activedirectory: 1 work
items need to be processed further
2019-10-23 09:52:00,049: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisionerCoordinator$ProvisioningStatus.lockForIncrementalProvisioningWhenNoFullSyncIsUnderway(139)
- - pspng_activedirectory: Locking group before incremental sync:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(Existing)
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] INFO
Provisioner.startProvisioningBatch(603) - - Starting provisioning batch of 1
items
2019-10-23 09:52:00,050: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper groups is sufficiently sized (0% full) (property
grouperGroupCacheSize=100000)
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned groups is sufficiently sized (0% full) (property
targetSystemGroupCacheSize=10000)
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of grouper subjects is sufficiently sized (0% full) (property
grouperSubjectCacheSize=200000)
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.warnAboutCacheSizeConcerns(684) - - pspng_activedirectory: Cache
of provisioned subjects is sufficiently sized (0% full) (property
targetSystemUserCacheSize=100000)
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.startProvisioningBatch(609) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.startProvisioningBatch(609) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.startProvisioningBatch(609) - - -->Work item:
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG]
2019-10-23 09:52:00,051: [DefaultQuartzScheduler_Worker-6] INFO
Provisioner.startProvisioningBatch(627) - - Information cached before
2019-10-23T09:51:13.746+02:00 will be ignored
2019-10-23 09:52:00,052: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,052: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,052: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.prepareGroupCache(999) - - Starting to cache group information
for 1 items
2019-10-23 09:52:00,053: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapGroupProvisioner.getLdapAttributesToFetch(572) - - Fetching without
membership attribute
2019-10-23 09:52:00,054: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.evaluateJexlExpression(777) - - Evaluated
SingleGroupSearchFilter Jexl expression: 'NEW_GROUP_WITH_DEBUG'
2019-10-23 09:52:00,054: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.evaluateJexlExpression(797) - - Evaluated entire
SingleGroupSearchFilter Jexl expression:
'(&(objectclass=group)(cn=NEW_GROUP_WITH_DEBUG))'
2019-10-23 09:52:00,054: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(531) - - pspng_activedirectory:
Searching for group XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT) with::
[org.ldaptive.SearchFilter@-1266814334::filter=(&(objectclass=group)(cn=NEW_GROUP_WITH_DEBUG)),
parameters={}]
2019-10-23 09:52:00,054: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapSystem.performLdapSearchRequest(796) - - Running ldap search:
<ou=group,dc=s,dc=univie,dc=ac,dc=at>/SUBTREE:
(&(objectclass=group)(cn=NEW_GROUP_WITH_DEBUG)) << {}
2019-10-23 09:52:00,054: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapSystem.performLdapSearchRequest(730) - - Doing ldap search:
[org.ldaptive.SearchFilter@-1266814334::filter=(&(objectclass=group)(cn=NEW_GROUP_WITH_DEBUG)),
parameters={}] / ou=group,dc=s,dc=univie,dc=ac,dc=at / [cn, gidNumber,
samAccountName, objectclass]
2019-10-23 09:52:00,057: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapSystem.performLdapSearchRequest(740) - - Using attribute-value paging
2019-10-23 09:52:00,057: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapSystem.performLdapSearchRequest(751) - - Using ldap search-result paging
2019-10-23 09:52:00,060: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapSystem$1.handle(807) - - Ldap result: CN=NEW_GROUP_WITH_DEBUG,...
2019-10-23 09:52:00,063: [DefaultQuartzScheduler_Worker-6] INFO
LdapSystem.performLdapSearchRequest(819) - - LDAP search returned 1 entries
2019-10-23 09:52:00,063: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapGroupProvisioner.fetchTargetSystemGroups(542) - - pspng_activedirectory:
Group search returned cn=new_group_with_debug,...
2019-10-23 09:52:00,063: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.cacheGroup(1125) - - Adding target-system group to cache:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,063: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.prepareUserCache(856) - - Starting to cache user information for
0 items
2019-10-23 09:52:00,063: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.provisionItem(1245) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,064: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.provisionItem(1245) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,064: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.provisionItem(1245) - - Starting provisioning of item:
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG]
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=false,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] INFO
Provisioner.processIncrementalSyncEvent(1395) - - Deleting provisioned
group: XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] INFO
LdapGroupProvisioner.deleteGroup(625) - - Deleting group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT) by deleting DN
cn=new_group_with_debug,...
2019-10-23 09:52:00,065: [DefaultQuartzScheduler_Worker-6] INFO
LdapSystem.performLdapDelete(404) - - active_directory: Deleting LDAP
object: cn=new_group_with_debug,...
2019-10-23 09:52:00,122: [DefaultQuartzScheduler_Worker-6] DEBUG
LdapProvisioner.makeCoalescedLdapChanges(479) - - pspng_activedirectory:
Making coalescedLdapChanges
2019-10-23 09:52:00,123: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.setStatus(132) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,123: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.setStatus(132) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,123: [DefaultQuartzScheduler_Worker-6] INFO
ProvisioningWorkItem.setStatus(132) - - Work item handled:
ProvisioningWorkItem[done=true,successful=true,msg=Modification
complete,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG]
2019-10-23 09:52:00,123: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.finishProvisioningBatch(700) - - Done with provisining batch
2019-10-23 09:52:00,126: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,126: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,127: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,127: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,128: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=true,successful=true,msg=Modification
complete,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,128: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisionerCoordinator$ProvisioningStatus.unlockAfterIncrementalProvisioning(160)
- - pspng_activedirectory: Unlocking group after incremental sync:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(Existing)
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangelogHandlingConfig.getFromChangelogTypesMap(162) - - ChangelogConfig:
GroupIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=idIndex
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] DEBUG
Provisioner.getGroupInfo(1693) - - pspng_activedirectory: Found PIT group
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectIdFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - ChangelogConfig:
SubjectSourceFieldLabels.get(2071243/ChangeLog type: group: deleteGroup)=null
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] DEBUG
ProvisioningWorkItem.getGroupInfo(203) - - WorkItem
ProvisioningWorkItem[done=true,successful=true,msg=Modification
complete,clog=clog #2071243 / ChangeLog type: group:
deleteGroup,group=XXX:YYY:NEW_GROUP_WITH_DEBUG] is related to Group:
XXX:YYY:NEW_GROUP_WITH_DEBUG/#12111(PIT)
2019-10-23 09:52:00,130: [DefaultQuartzScheduler_Worker-6] INFO
PspChangelogConsumerShim.processChangeLogEntries(116) - - Provisioning batch
summary: 1 successes/0 failures. Duration=00.098s
2019-10-23 09:52:00,134: [DefaultQuartzScheduler_Worker-6] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071242, 0: number of records found to process: 1,
0: processed to record number: 2071243, totalRecordsProcessed: 1
2019-10-23 09:52:04,018: [DefaultQuartzScheduler_Worker-7] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071242, 0: number of records found to process: 1, 0:
processed to record number: 2071243, totalRecordsProcessed: 1
2019-10-23 09:53:00,021: [DefaultQuartzScheduler_Worker-9] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:53:00,040: [DefaultQuartzScheduler_Worker-10] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 09:53:00,043: [DefaultQuartzScheduler_Worker-10] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:53:04,015: [DefaultQuartzScheduler_Worker-5] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:54:00,018: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:54:00,035: [DefaultQuartzScheduler_Worker-3] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 09:54:00,046: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:54:04,016: [DefaultQuartzScheduler_Worker-4] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:55:00,016: [DefaultQuartzScheduler_Worker-7] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:55:00,032: [DefaultQuartzScheduler_Worker-8] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 09:55:00,034: [DefaultQuartzScheduler_Worker-8] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:55:04,017: [DefaultQuartzScheduler_Worker-10] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:56:00,026: [DefaultQuartzScheduler_Worker-1] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: grouperRules, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:56:00,039: [DefaultQuartzScheduler_Worker-2] DEBUG
PspChangelogConsumerShim.<init>(43) - - Constructing
PspngChangelogConsumerShim
2019-10-23 09:56:00,044: [DefaultQuartzScheduler_Worker-2] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: pspng_activedirectory,
last sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0
2019-10-23 09:56:04,021: [DefaultQuartzScheduler_Worker-3] DEBUG
ChangeLogHelper.processRecords(314) - - consumerName: syncGroups, last
sequence processed: 2071243, 0: number of records found to process: 0,
totalRecordsProcessed: 0

[grouper-users] AD Provisioning not working on delete, Oliver Trieu, 10/17/2019
- RE: [grouper-users] AD Provisioning not working on delete, Hyzer, Chris, 10/21/2019
  - Re: [grouper-users] AD Provisioning not working on delete, Oliver Trieu, 10/22/2019
    - Re: [grouper-users] AD Provisioning not working on delete, Jeffrey Williams, 10/22/2019
      - Re: [grouper-users] AD Provisioning not working on delete, Oliver Trieu, 10/23/2019
        
        Re: [grouper-users] AD Provisioning not working on delete, Jeffrey Williams, 10/24/2019

List archive

Re: [grouper-users] AD Provisioning not working on delete