Skip to Content.
Sympa Menu

grouper-dev - [grouper-dev] Bug when using the baseStem configuration with AD (and more ldaps?)

Subject: Grouper Developers Forum

List archive

[grouper-dev] Bug when using the baseStem configuration with AD (and more ldaps?)


Chronological Thread 
  • From: Gagné Sébastien <>
  • To: <>
  • Subject: [grouper-dev] Bug when using the baseStem configuration with AD (and more ldaps?)
  • Date: Tue, 6 Mar 2012 14:15:27 -0500

Hi,

I encountered a weird bug when retesting our installation.

 

I specified a base stem in grouper.properties (edu.internet2.middleware.psp.baseStem=UdeM). This stem will start a new branch in our AD (i.e. ou=UdeM,ou=People,dc=test,dc=ca) which does not currently exists (ou=People does exist). This caused bulkSync and the changelog Provisionning to return error each time they tried to provision a new stem I created under UdeM (i.e. UdeM:Test1). I tried a lot of things before finding the problem : you need to manually create the baseStem in AD, doing so solved all the problems and allowed me to do a full sync without problems.

 

Is this normal behaviour ? I would think that Grouper should provision the baseStem if it’s required in the LDAP. Should I open a JIRA about it ?

 

 

I should mention that bulkDiff and bulkCalc were returning the appropriate data during all this time.

 

Here is our trace logs for the exception during bulkSync :

 

--- in the console ---

 

<psp:bulkSyncResponse xmlns:psp='http://grouper.internet2.edu/psp' status='failure' requestID='2012/03/06-13:08:57.833'>

  <psp:syncResponse>

    <addResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' requestID='2012/03/06-13:08:58.151' error='customError'>

      <errorMessage>[LDAP: error code 32 - 0000208D: NameErr: DSID-0310020A, problem 2001 (NO_OBJECT), data 0, best match of:

        'OU=People,DC=umontreal,DC=ca'

_]</errorMessage>

    </addResponse>

    <psp:id ID='UdeM:tt1'/>

  </psp:syncResponse>

</psp:bulkSyncResponse>

 

 

--- In the logs ---

 

2012-03-06 13:08:50,533: [main] WARN  ApiConfig.printConfigOnce(212) -  - Grouper starting up: version: 2.1.0, build date: 2012/03/05 13:12:33, env: <no label configured>

grouper.properties read from: /app/grouper/grouper.apiBinary-2.1.0/conf/grouper.properties

Grouper current directory is: /app/grouper/grouper.apiBinary-2.1.0/bin

log4j.properties read from:   /app/grouper/grouper.apiBinary-2.1.0/conf/log4j.properties

Grouper logs are not using log4j: class org.apache.commons.logging.impl.SLF4JLocationAwareLog

grouper.hibernate.properties: /app/grouper/grouper.apiBinary-2.1.0/conf/grouper.hibernate.properties

grouper.hibernate.properties: dv_grouper@jdbc:oracle:thin:@s-or-DVGDIs-dev1.dit.umontreal.ca:1521:DVGIAPPA

sources.xml read from:        /app/grouper/grouper.apiBinary-2.1.0/conf/sources.xml

sources.xml groupersource id: g:gsa

sources.xml ldap source id:   ldap: ldap.properties

sources.xml groupersource id: grouperEntities

2012-03-06 13:08:55,334: [main] INFO  EventLog.info(141) -  - [ecbf9c3265754050bab89553cb09e13b,'GrouperSystem','application'] session: start (129ms)

2012-03-06 13:08:55,387: [main] INFO  EventLog.info(141) -  - [6d717a4adccb4b0b9fad59c03c8057d0,'GrouperSystem','application'] session: start (3ms)

2012-03-06 13:08:55,405: [main] INFO  EventLog.info(141) -  - [5e6b99abb0dd47d897ea453e7e36723a,'GrouperSystem','application'] session: start (0ms)

2012-03-06 13:08:55,465: [main] INFO  EventLog.info(141) -  - [8dde71641a91402380ceda240239b9d8,'GrouperSystem','application'] session: start (5ms)

2012-03-06 13:08:55,825: [main] INFO  EventLog.info(141) -  - [6fca0c69a91e417aae42c3644ee2015c,'GrouperSystem','application'] session: start (1ms)

2012-03-06 13:08:56,080: [main] INFO  EventLog.info(141) -  - [a12c6b2548114d92a962b0a89d6c2adb,'GrouperSystem','application'] session: start (0ms)

2012-03-06 13:08:56,089: [main] INFO  EventLog.info(141) -  - [50a2f06f2ae144f787512505ab80a520,'GrouperSystem','application'] session: start (1ms)

2012-03-06 13:08:56,798: [main] INFO  EventLog.info(141) -  - [a2972065bd624c0191763056269bf6d0,'GrouperSystem','application'] session: start (5ms)

2012-03-06 13:08:56,809: [main] INFO  EventLog.info(141) -  - [3f36c3789313421399a648277177ffc9,'GrouperSystem','application'] session: start (7ms)

2012-03-06 13:08:56,811: [main] INFO  EventLog.info(141) -  - [4b2bb66ce4084abd8a35ec5ab6d1d7aa,'GrouperSystem','application'] session: start (1ms)

2012-03-06 13:08:56,818: [main] INFO  EventLog.info(141) -  - [4b2bb66ce4084abd8a35ec5ab6d1d7aa,'GrouperSystem','application'] add group type: 'grouperLoader' (6ms)

2012-03-06 13:08:56,948: [main] INFO  EventLog.info(141) -  - [d899fc36a79b43fba9518da56399a0bf,'GrouperSystem','application'] session: start (1ms)

2012-03-06 13:08:56,950: [main] INFO  EventLog.info(141) -  - [5522f0dad5e545359cf9a6215bd4eabd,'GrouperSystem','application'] session: start (1ms)

2012-03-06 13:08:57,818: [main] INFO  PspCLI.run(126) -  - Starting psp

2012-03-06 13:08:57,829: [main] INFO  Psp.execute(750) -  - Psp 'psp' - BulkSync BulkSyncRequest[id=edu.internet2.middleware.psp.spml.request.BulkProvisioningRequest,requestID=<null>,returnData=everything,>

2012-03-06 13:08:57,833: [main] INFO  Psp.execute(754) -  - Psp 'psp' - BulkSync SPML:

<psp:bulkSyncRequest xmlns:psp='http://grouper.internet2.edu/psp' returnData='everything' >

  <psp:id ID='edu.internet2.middleware.psp.spml.request.BulkProvisioningRequest'/>

</psp:bulkSyncRequest>

 

2012-03-06 13:08:57,834: [main] INFO  Psp.execute(593) -  - Psp 'psp' - BulkDiff BulkDiffRequest[id=edu.internet2.middleware.psp.spml.request.BulkProvisioningRequest,requestID=2012/03/06-13:08:57.834,returnData=everything,>

2012-03-06 13:08:57,834: [main] INFO  Psp.execute(597) -  - Psp 'psp' - BulkDiff SPML:

<psp:bulkDiffRequest xmlns:psp='http://grouper.internet2.edu/psp' requestID='2012/03/06-13:08:57.834' returnData='everything' >

  <psp:id ID='edu.internet2.middleware.psp.spml.request.BulkProvisioningRequest'/>

</psp:bulkDiffRequest>

 

2012-03-06 13:08:57,888: [main] INFO  EventLog.info(141) -  - [14a5cb07b37945afa31fd61cdff9f336,'GrouperSystem','application'] session: start (4ms)

2012-03-06 13:08:57,907: [main] WARN  Psp.getAllSourceIdentifiers(1447) -  - PSP 'psp' - Unable to resolve attribute 'groupNames'

2012-03-06 13:08:57,908: [main] INFO  Psp.execute(1030) -  - Psp 'psp' - Diff DiffRequest[id=UdeM:tt1,requestID=2012/03/06-13:08:57.908,returnData=everything,schemaEntityRef=SchemaEntityRef[targetID=ldap,entityName=stem,isContainer=false]]

2012-03-06 13:08:57,909: [main] INFO  Psp.execute(1034) -  - Psp 'psp' - Diff XML:

<psp:diffRequest xmlns:psp='http://grouper.internet2.edu/psp' requestID='2012/03/06-13:08:57.908' returnData='everything'>

  <psp:id ID='UdeM:tt1'/>

  <psp:schemaEntity targetID='ldap' entityName='stem'/>

</psp:diffRequest>

 

2012-03-06 13:08:57,911: [main] INFO  Psp.execute(885) -  - Psp 'psp' - Calc CalcRequest[id=UdeM:tt1,requestID=2012/03/06-13:08:57.911,returnData=everything,schemaEntityRef=SchemaEntityRef[targetID=ldap,entityName=stem,isContainer=false]]

2012-03-06 13:08:57,911: [main] INFO  Psp.execute(889) -  - Psp 'psp' - Calc XML:

<psp:calcRequest xmlns:psp='http://grouper.internet2.edu/psp' requestID='2012/03/06-13:08:57.911' returnData='everything'>

  <psp:id ID='UdeM:tt1'/>

  <psp:schemaEntity targetID='ldap' entityName='stem'/>

</psp:calcRequest>

 

2012-03-06 13:08:57,944: [main] INFO  Psp.execute(914) -  - Psp 'psp' - Calc CalcResponse[status=success,requestID=2012/03/06-13:08:57.911]

2012-03-06 13:08:57,945: [main] INFO  Psp.execute(916) -  - Psp 'psp' - Calc XML:

<psp:calcResponse xmlns:psp='http://grouper.internet2.edu/psp' status='success' requestID='2012/03/06-13:08:57.911'>

  <psp:id ID='UdeM:tt1'/>

  <psp:pso entityName='stem'>

    <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' 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>tt1</dsml:value>

      </dsml:attr>

      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='description'>

        <dsml:value>tt1</dsml:value>

      </dsml:attr>

    </data>

  </psp:pso>

</psp:calcResponse>

 

2012-03-06 13:08:57,945: [main] INFO  BaseSpmlProvider.execute(285) -  - Target 'psp' - Lookup LookupRequest[psoID=PSOIdentifier[id='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca',targetID=ldap,containerID=<null>],returnData=everything,requestID=2012/03/06-13:08:57.945]

2012-03-06 13:08:57,946: [main] INFO  BaseSpmlProvider.execute(289) -  - Target 'psp' - Lookup XML:

<lookupRequest xmlns='urn:oasis:names:tc:SPML:2:0' requestID='2012/03/06-13:08:57.945' returnData='everything'>

  <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' targetID='ldap'/>

</lookupRequest>

 

2012-03-06 13:08:57,946: [main] INFO  BaseSpmlProvider.execute(285) -  - Target 'ldap' - Lookup LookupRequest[psoID=PSOIdentifier[id='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca',targetID=ldap,containerID=<null>],returnData=everything,requestID=2012/03/06-13:08:57.945]

2012-03-06 13:08:57,947: [main] INFO  BaseSpmlProvider.execute(289) -  - Target 'ldap' - Lookup XML:

<lookupRequest xmlns='urn:oasis:names:tc:SPML:2:0' requestID='2012/03/06-13:08:57.945' returnData='everything'>

  <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' targetID='ldap'/>

</lookupRequest>

 

2012-03-06 13:08:58,149: [main] ERROR BaseSpmlProvider.execute(320) -  - Target 'ldap' - Lookup LookupResponse[pso=<null>,status=failure,error=noSuchIdentifier,errorMessages={},requestID=2012/03/06-13:08:57.945]

2012-03-06 13:08:58,149: [main] ERROR BaseSpmlProvider.execute(322) -  - Target 'ldap' - Lookup XML:

<lookupResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' requestID='2012/03/06-13:08:57.945' error='noSuchIdentifier'/>

 

2012-03-06 13:08:58,150: [main] ERROR BaseSpmlProvider.execute(320) -  - Target 'psp' - Lookup LookupResponse[pso=<null>,status=failure,error=noSuchIdentifier,errorMessages={},requestID=2012/03/06-13:08:57.945]

2012-03-06 13:08:58,150: [main] ERROR BaseSpmlProvider.execute(322) -  - Target 'psp' - Lookup XML:

<lookupResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' requestID='2012/03/06-13:08:57.945' error='noSuchIdentifier'/>

 

2012-03-06 13:08:58,154: [main] INFO  Psp.execute(1059) -  - Psp 'psp' - Diff DiffResponse[status=success,requestID=2012/03/06-13:08:57.908]

2012-03-06 13:08:58,154: [main] INFO  Psp.execute(1061) -  - Psp 'psp' - Diff XML:

<psp:diffResponse xmlns:psp='http://grouper.internet2.edu/psp' status='success' requestID='2012/03/06-13:08:57.908'>

  <addRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='stem' requestID='2012/03/06-13:08:58.151' targetId='ldap' returnData='everything'>

    <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' 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>tt1</dsml:value>

      </dsml:attr>

      <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='description'>

        <dsml:value>tt1</dsml:value>

      </dsml:attr>

    </data>

  </addRequest>

  <psp:id ID='UdeM:tt1'/>

</psp:diffResponse>

 

2012-03-06 13:08:58,155: [main] INFO  Psp.execute(622) -  - Psp 'psp' - BulkDiff BulkDiffResponse[status=success,requestID=2012/03/06-13:08:57.834]

2012-03-06 13:08:58,155: [main] INFO  Psp.execute(624) -  - Psp 'psp' - BulkDiff SPML:

<psp:bulkDiffResponse xmlns:psp='http://grouper.internet2.edu/psp' status='success' requestID='2012/03/06-13:08:57.834'>

  <psp:diffResponse status='success' requestID='2012/03/06-13:08:57.908'>

    <addRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='stem' requestID='2012/03/06-13:08:58.151' targetId='ldap' returnData='everything'>

      <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' 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>tt1</dsml:value>

        </dsml:attr>

        <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='description'>

          <dsml:value>tt1</dsml:value>

        </dsml:attr>

      </data>

    </addRequest>

    <psp:id ID='UdeM:tt1'/>

  </psp:diffResponse>

</psp:bulkDiffResponse>

 

2012-03-06 13:08:58,156: [main] INFO  BaseSpmlProvider.execute(153) -  - Target 'ldap' - Add AddRequest[psoID=PSOIdentifier[id='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca',targetID=ldap,containerID=<null>],targetID=ldap,returnData=everything,requestID=2012/03/06-13:08:58.151]

2012-03-06 13:08:58,156: [main] INFO  BaseSpmlProvider.execute(157) -  - Target 'ldap' - Add XML:

<addRequest xmlns='urn:oasis:names:tc:SPML:2:0' entityName='stem' requestID='2012/03/06-13:08:58.151' targetId='ldap' returnData='everything'>

  <psoID ID='ou=tt1,ou=UdeM,OU=People,DC=umontreal,DC=ca' 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>tt1</dsml:value>

    </dsml:attr>

    <dsml:attr xmlns:dsml='urn:oasis:names:tc:DSML:2:0:core' name='description'>

      <dsml:value>tt1</dsml:value>

    </dsml:attr>

  </data>

</addRequest>

 

2012-03-06 13:08:58,367: [main] ERROR BaseSpmlProvider.execute(188) -  - Target 'ldap' - Add AddResponse[pso=<null>,status=failure,error=customError,errorMessages={[LDAP: error code 32 - 0000208D: NameErr: DSID-0310020A, problem 2001 (NO_OBJECT), data 0, best match of:

        'OU=People,DC=umontreal,DC=ca'

_]},requestID=2012/03/06-13:08:58.151]

2012-03-06 13:08:58,368: [main] ERROR BaseSpmlProvider.execute(190) -  - Target 'ldap' - Add XML:

<addResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' requestID='2012/03/06-13:08:58.151' error='customError'>

  <errorMessage>[LDAP: error code 32 - 0000208D: NameErr: DSID-0310020A, problem 2001 (NO_OBJECT), data 0, best match of:

        'OU=People,DC=umontreal,DC=ca'

_]</errorMessage>

</addResponse>

 

2012-03-06 13:08:58,368: [main] ERROR Psp.execute(785) -  - Psp 'psp' - BulkSync BulkSyncResponse[status=failure,error=<null>,errorMessages={},requestID=2012/03/06-13:08:57.833]

2012-03-06 13:08:58,369: [main] ERROR Psp.execute(787) -  - Psp 'psp' -  BulkSync SPML:

<psp:bulkSyncResponse xmlns:psp='http://grouper.internet2.edu/psp' status='failure' requestID='2012/03/06-13:08:57.833'>

  <psp:syncResponse>

    <addResponse xmlns='urn:oasis:names:tc:SPML:2:0' status='failure' requestID='2012/03/06-13:08:58.151' error='customError'>

      <errorMessage>[LDAP: error code 32 - 0000208D: NameErr: DSID-0310020A, problem 2001 (NO_OBJECT), data 0, best match of:

        'OU=People,DC=umontreal,DC=ca'

_]</errorMessage>

    </addResponse>

    <psp:id ID='UdeM:tt1'/>

  </psp:syncResponse>

</psp:bulkSyncResponse>


Archive powered by MHonArc 2.6.16.

Top of Page