Grouper Users - Open Discussion List

[Dominique Petitpierre <>]

Hello,

in Grouper 2.1.3 PSP logs an ERROR level message when it processes a
change that occured in a branch that is not synchronized. For example,
the log in annexe shows such a error message for a change occurring in
etc:sysadmingroup, while the branch "etc" is explicitly excluded in
the rules of psp-resolver.xml:

ERROR .... status=failure,error=noSuchIdentifier,errorMessages={Unable 
to calculate provisioned object.}

In my case there is a large number of non synchronized branches thus
causing a lot of these systematic spurious ERROR messages.

The same thing happens when one adds a new folder or group that does
not occur yet in the target LDAP directory (cf. extract in second
annexe):

ERROR .... status=failure,error=noSuchIdentifier,errorMessages={}

In both cases the situation is completely normal and it is annoying to
have to sort out the real ERROR level messages from these spurious ones.

It would be better that, in these cases, PSP would only log a message
reporting such information (i.e. the fact that a branch is not
synchronized or that the folder is inexistent in the LDAP directory)
at INFO or even DEBUG level.

Best regards,
Dominique
--
Mr Dominique Petitpierre, user=Dominique.Petitpierre domain=unige.ch
IT Division, University of Geneva, Switzerland
2013-04-27 18:36:00,028: [DefaultQuartzScheduler_Worker-6] INFO  
PspChangeLogConsumer.processChangeLogEntry(566) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
18:35:28.631,sequence=34797,category=membership,actionname=addMembership,contextId=840def38d6d24e5496ec8db39ac33120,id=5b7cdae0bf93453c89d6529c3509cf1b,fieldName=members,,sourceId=people.unige.ch,membershipType=flattened,groupId=c9a1dc271bd64ee2880a104167f7e2c8,groupName=etc:sysadmingroup,memberId=7c757276de594c89b916ecf6bbe1aab7,fieldId=f689aba254d3421b9888944fa9b37d00]'
2013-04-27 18:36:00,029: [DefaultQuartzScheduler_Worker-6] INFO  
Psp.execute(980) -  - Psp 'psp' - Calc 
CalcRequest[id=change_log_sequence_number:34797,requestID=2013/04/27-18:36:00.029,returnData=everything]
2013-04-27 18:36:00,057: [DefaultQuartzScheduler_Worker-6] ERROR 
Psp.execute(1015) -  - Psp 'psp' - Calc 
CalcResponse[id=change_log_sequence_number:34797,status=failure,error=noSuchIdentifier,errorMessages={Unable
 to calculate provisioned object.},requestID=2013/04/27-18:36:00.029]
2013-04-27 18:36:00,058: [DefaultQuartzScheduler_Worker-6] INFO  
PspChangeLogConsumer.processChangeLogEntry(573) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
18:35:28.631,sequence=34797,category=membership,actionname=addMembership,contextId=840def38d6d24e5496ec8db39ac33120]'
 Finished processing. Elapsed time 0:00:00.028
2013-04-27 20:02:00,027: [DefaultQuartzScheduler_Worker-7] INFO  
PspChangeLogConsumer.processChangeLogEntry(566) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
20:01:08.0,sequence=34796,category=stem,actionname=addStem,contextId=abbedb740e474550930b50ba22dfe18a,id=8e49a63217a943ab9796223165cf7368,name=application:portail.unige.ch:test,parentStemId=153b71dc783a4361946eb080e1a9e3cc,displayName=Application:portail.unige.ch:Test,description=<null>]'
2013-04-27 20:02:00,028: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1405) -  - Psp 'psp' - Sync 
SyncRequest[id=application:portail.unige.ch:test,requestID=2013/04/27-20:02:00.028,returnData=everything]
2013-04-27 20:02:00,029: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1140) -  - Psp 'psp' - Diff 
DiffRequest[id=application:portail.unige.ch:test,requestID=2013/04/27-20:02:00.029,returnData=everything]
2013-04-27 20:02:00,029: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(980) -  - Psp 'psp' - Calc 
CalcRequest[id=application:portail.unige.ch:test,requestID=2013/04/27-20:02:00.029,returnData=everything]
2013-04-27 20:02:00,049: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1009) -  - Psp 'psp' - Calc 
CalcResponse[id=application:portail.unige.ch:test,status=success,requestID=2013/04/27-20:02:00.029,pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]]]
2013-04-27 20:02:00,049: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(285) -  - Target 'psp' - Lookup 
LookupRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],returnData=everything,requestID=2013/04/27-20:02:00.049]
2013-04-27 20:02:00,050: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(285) -  - Target 'ldap' - Lookup 
LookupRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],returnData=everything,requestID=2013/04/27-20:02:00.049]
2013-04-27 20:02:00,050: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(289) -  - Target 'ldap' - Lookup XML:
<lookupRequest xmlns='urn:oasis:names:tc:SPML:2:0' 
requestID='2013/04/27-20:02:00.049' returnData='everything'>
  <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
</lookupRequest>

2013-04-27 20:02:00,054: [DefaultQuartzScheduler_Worker-7] ERROR 
BaseSpmlProvider.execute(320) -  - Target 'ldap' - Lookup 
LookupResponse[pso=<null>,status=failure,error=noSuchIdentifier,errorMessages={},requestID=2013/04/27-20:02:00.049]
2013-04-27 20:02:00,055: [DefaultQuartzScheduler_Worker-7] ERROR 
BaseSpmlProvider.execute(322) -  - Target 'ldap' - Lookup XML:
<lookupResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' 
requestID='2013/04/27-20:02:00.049' error='noSuchIdentifier'/>

2013-04-27 20:02:00,055: [DefaultQuartzScheduler_Worker-7] ERROR 
BaseSpmlProvider.execute(320) -  - Target 'psp' - Lookup 
LookupResponse[pso=<null>,status=failure,error=noSuchIdentifier,errorMessages={},requestID=2013/04/27-20:02:00.049]
2013-04-27 20:02:00,056: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1169) -  - Psp 'psp' - Diff 
DiffResponse[id=application:portail.unige.ch:test,status=success,requestID=2013/04/27-20:02:00.029,add=AddRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],targetID=ldap,returnData=everything,requestID=2013/04/27-20:02:00.056]]
2013-04-27 20:02:00,056: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(153) -  - Target 'psp' - Add 
AddRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],targetID=ldap,returnData=everything,requestID=2013/04/27-20:02:00.056]
2013-04-27 20:02:00,057: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(153) -  - Target 'ldap' - Add 
AddRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],targetID=ldap,returnData=everything,requestID=2013/04/27-20:02:00.056]
2013-04-27 20:02:00,057: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(157) -  - Target 'ldap' - Add XML:
<addRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='stem' 
requestID='2013/04/27-20:02:00.056' targetId='ldap' returnData='everything'>
  <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
  <data>
    <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='objectClass'>
      <dsml:value>top</dsml:value>
      <dsml:value>organizationalUnit</dsml:value>
    </dsml:attr>
    <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='ou'>
      <dsml:value>test</dsml:value>
    </dsml:attr>
    <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='description'>
      <dsml:value>test</dsml:value>
    </dsml:attr>
  </data>
</addRequest>

2013-04-27 20:02:00,118: [DefaultQuartzScheduler_Worker-7] INFO  
LdapSpmlTarget.execute(252) -  - Target 'ldap' - Created 
'AddRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],targetID=ldap,returnData=everything,requestID=2013/04/27-20:02:00.056]'
2013-04-27 20:02:00,118: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(285) -  - Target 'ldap' - Lookup 
LookupRequest[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],returnData=everything,requestID=<null>]
2013-04-27 20:02:00,119: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(289) -  - Target 'ldap' - Lookup XML:
<lookupRequest xmlns='urn:oasis:names:tc:SPML:2:0' returnData='everything'>
  <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
</lookupRequest>

2013-04-27 20:02:00,121: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(314) -  - Target 'ldap' - Lookup 
LookupResponse[pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]],status=success,requestID=2013/04/27-20:02:00.119]
2013-04-27 20:02:00,122: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(316) -  - Target 'ldap' - Lookup XML:
<lookupResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='success' 
requestID='2013/04/27-20:02:00.119'>
  <pso entityName='stem'>
    <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
    <data>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='objectClass'>
        <dsml:value>organizationalUnit</dsml:value>
        <dsml:value>top</dsml:value>
      </dsml:attr>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='ou'>
        <dsml:value>test</dsml:value>
      </dsml:attr>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='description'>
        <dsml:value>test</dsml:value>
      </dsml:attr>
    </data>
  </pso>
</lookupResponse>

2013-04-27 20:02:00,122: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(182) -  - Target 'ldap' - Add 
AddResponse[pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]],status=success,requestID=2013/04/27-20:02:00.056]
2013-04-27 20:02:00,122: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(184) -  - Target 'ldap' - Add XML:
<addResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='success' 
requestID='2013/04/27-20:02:00.056'>
  <pso entityName='stem'>
    <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
    <data>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='objectClass'>
        <dsml:value>organizationalUnit</dsml:value>
        <dsml:value>top</dsml:value>
      </dsml:attr>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='ou'>
        <dsml:value>test</dsml:value>
      </dsml:attr>
      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' 
name='description'>
        <dsml:value>test</dsml:value>
      </dsml:attr>
    </data>
  </pso>
</addResponse>

2013-04-27 20:02:00,123: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(182) -  - Target 'psp' - Add 
AddResponse[pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]],status=success,requestID=2013/04/27-20:02:00.056]
2013-04-27 20:02:00,123: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1434) -  - Psp 'psp' - Sync 
SyncResponse[id=application:portail.unige.ch:test,status=success,requestID=2013/04/27-20:02:00.028,AddResponse[pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]],status=success,requestID=2013/04/27-20:02:00.056]]
2013-04-27 20:02:00,123: [DefaultQuartzScheduler_Worker-7] INFO  
PspChangeLogConsumer.executeSync(296) -  - PSP Consumer 'psp' - Change log 
entry 'ChangeLogEntry[timestamp=2013-04-27 
20:01:08.0,sequence=34796,category=stem,actionname=addStem,contextId=abbedb740e474550930b50ba22dfe18a]'
 Sync was successful 
'SyncResponse[id=application:portail.unige.ch:test,status=success,requestID=2013/04/27-20:02:00.028,AddResponse[pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]],status=success,requestID=2013/04/27-20:02:00.056]]'
2013-04-27 20:02:00,124: [DefaultQuartzScheduler_Worker-7] INFO  
PspChangeLogConsumer.processChangeLogEntry(573) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
20:01:08.0,sequence=34796,category=stem,actionname=addStem,contextId=abbedb740e474550930b50ba22dfe18a]'
 Finished processing. Elapsed time 0:00:00.095
2013-04-27 20:02:00,124: [DefaultQuartzScheduler_Worker-7] INFO  
PspChangeLogConsumer.processChangeLogEntry(566) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
20:01:08.15,sequence=34799,category=stem,actionname=updateStem,contextId=b95e3b64646a475789fee999ffaf0bf1,id=8e49a63217a943ab9796223165cf7368,name=application:portail.unige.ch:test,parentStemId=153b71dc783a4361946eb080e1a9e3cc,displayName=Application:portail.unige.ch:Test,description=test,propertyChanged=description,propertyOldValue=<null>,propertyNewValue=test]'
2013-04-27 20:02:00,124: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(980) -  - Psp 'psp' - Calc 
CalcRequest[id=change_log_sequence_number:34799,requestID=2013/04/27-20:02:00.124,returnData=data]
2013-04-27 20:02:00,146: [DefaultQuartzScheduler_Worker-7] INFO  
Psp.execute(1009) -  - Psp 'psp' - Calc 
CalcResponse[id=change_log_sequence_number:34799,status=success,requestID=2013/04/27-20:02:00.124,pso=PSO[psoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>]]]
2013-04-27 20:02:00,147: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(417) -  - Target 'psp' - Search 
SearchRequest[query=Query[filter=<dsml:filter 
xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core'>  <dsml:equalityMatch 
name='description'>    <dsml:value>test</dsml:value>  
</dsml:equalityMatch></dsml:filter>,basePsoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],scope=pso,targetID=ldap],returnData=identifier,maxSelect=0,requestID=2013/04/27-20:02:00.147]
2013-04-27 20:02:00,147: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(417) -  - Target 'ldap' - Search 
SearchRequest[query=Query[filter=<dsml:filter 
xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core'>  <dsml:equalityMatch 
name='description'>    <dsml:value>test</dsml:value>  
</dsml:equalityMatch></dsml:filter>,basePsoID=PSOIdentifier[id='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch',targetID=ldap,containerID=<null>],scope=pso,targetID=ldap],returnData=identifier,maxSelect=0,requestID=2013/04/27-20:02:00.147]
2013-04-27 20:02:00,148: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(421) -  - Target 'ldap' - Search XML:
<spmlsearch:searchRequest xmlns='urn:oasis:names:tc:SPML:2:0' 
xmlns:spmlsearch='urn:oasis:names:tc:SPML:2:0:search' 
requestID='2013/04/27-20:02:00.147' returnData='identifier'>
  <spmlsearch:query targetID='ldap' scope='pso'>
    <dsml:filter xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core'>
      <dsml:equalityMatch name='description'>
        <dsml:value>test</dsml:value>
      </dsml:equalityMatch>
    </dsml:filter>
    <spmlsearch:basePsoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
  </spmlsearch:query>
</spmlsearch:searchRequest>

2013-04-27 20:02:00,150: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(446) -  - Target 'ldap' - Search 
SearchResponse[psos=1,status=success,requestID=2013/04/27-20:02:00.147]
2013-04-27 20:02:00,150: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(448) -  - Target 'ldap' - Search XML:
<spmlsearch:searchResponse xmlns='urn:oasis:names:tc:SPML:2:0' 
xmlns:spmlsearch='urn:oasis:names:tc:SPML:2:0:search' status='success' 
requestID='2013/04/27-20:02:00.147'>
  <spmlsearch:pso entityName='stem'>
    <psoID 
ID='ou=test,ou=portail.unige.ch,ou=application,ou=Groups,dc=unige,dc=ch' 
targetID='ldap'/>
  </spmlsearch:pso>
</spmlsearch:searchResponse>

2013-04-27 20:02:00,150: [DefaultQuartzScheduler_Worker-7] INFO  
BaseSpmlProvider.execute(446) -  - Target 'psp' - Search 
SearchResponse[psos=1,status=success,requestID=2013/04/27-20:02:00.147]
2013-04-27 20:02:00,150: [DefaultQuartzScheduler_Worker-7] INFO  
PspChangeLogConsumer.processChangeLogEntry(573) -  - PSP Consumer 'psp' - 
Change log entry 'ChangeLogEntry[timestamp=2013-04-27 
20:01:08.15,sequence=34799,category=stem,actionname=updateStem,contextId=b95e3b64646a475789fee999ffaf0bf1]'
 Finished processing. Elapsed time 0:00:00.026